Thursday, March 04, 2010

JMX, JVisualVM

监控对系统来说是个非常重要的功能,比如如果你的系统能够显示一个动态变化的每10秒刷新一次的实时销量趋势图,客户一定会非常开心,事实上这个功能也是非常重要的,不是一个玩具。
我最近一直在想这个问题,因为这段时间维护系统开始从一个新的角度去看系统开发,开始更多的考虑系统可维护性的问题(对于多数开发者他们只关注开发阶段的问题,但是一个软件系统的生命周期中90%都处于维护阶段),其中监控维护者(系统监控)和客户(偏重业务监控)都需要的工具。
自然而然的我就想到了JMX,这个技术已经出现很长时间了,有成熟的规范,有丰富的资料。但是我仍然再想为什么要用JMX来实现监控呢? 有什么优势?我自己定义web service,也一样可以暴露监控和管理接口,如果这样来做那就是轻车熟路,技术上没有门槛。而JMX,对于一套专属的系统来说,规范有多少意义,这些接口只有管理系统可以看到,我宁愿采用定制的,轻型的,一切自己掌控的方案。 如果说因为这是JCP的规范,所以我们应该采用JMX,老实说,理由很牵强。
但是我还是看了一遍sun的(O,oracle的)JMX tutorial,现在我想我有了其他的理由,这些理由比JCP更有说服力。
1)与JVisualVM的直接整合。
2)JDK自带的,无需第三方包
3)很容易,学习曲线非常低

1。 与JVisualVM的直接整合
这是一个很酷的特性,我直接开始想到真实系统的应用场景。系统管理员可以用JVisualVM来监控和管理系统,而定制开发的web系统来管理业务数据,这样,我们只需要写服务器端的代码,而客户端就直接是JVisualVM,简单轻松。看看我实验的代码(来自sun jmx tutorial)

* 定义一个StandardMBean(JMX规范中,接口名以MBean结束,比如XXXMBean,而对应的实现类直接去掉MBean就可以了,约定优于配置)
package org.jmx;
public interface HelloMBean {
public void sayHello();
public int add(int x, int y);
public String getName();
public int getCacheSize();
public void setCacheSize(int size);
}


package org.jmx;
import javax.management.AttributeChangeNotification;
import javax.management.MBeanNotificationInfo;
import javax.management.Notification;
import javax.management.NotificationBroadcasterSupport;
public class Hello extends NotificationBroadcasterSupport implements HelloMBean {
public void sayHello() {
System.out.println("hello, world");
}
public int add(int x, int y) {
return x + y;
}
public String getName() {
return this.name;
}
public int getCacheSize() {
return this.cacheSize;
}
public synchronized void setCacheSize(int size) {
int oldSize = this.cacheSize;
this.cacheSize = size;
System.out.println("Cache size now " + this.cacheSize);
Notification n = new AttributeChangeNotification(this, sequenceNumber++, System
.currentTimeMillis(), "CacheSize changed", "CacheSize", "int", oldSize,
this.cacheSize);
sendNotification(n);
}

@Override
public MBeanNotificationInfo[] getNotificationInfo() {
String[] types = new String[] { AttributeChangeNotification.ATTRIBUTE_CHANGE };
String name = AttributeChangeNotification.class.getName();
String description = "An attribute of this MBean has changed";
MBeanNotificationInfo info = new MBeanNotificationInfo(types, name, description);
return new MBeanNotificationInfo[] { info };
}

private final String name = "Reginald";
private int cacheSize = DEFAULT_CACHE_SIZE;
private static final int DEFAULT_CACHE_SIZE = 200;
private long sequenceNumber = 1;
}


在实现类中继承了NotificationBroadcasterSupport ,这样可以向注册的listener发送通知,后来可以看到我从客户端注册了一个listener,这样服务器端发送通知之后,客户端就可以收到(好像在JVisualVM的场景中没有什么作用,但是自定义客户端则非常重要)。

* 启动Server端
package org.jmx;

import java.lang.management.ManagementFactory;
import javax.management.MBeanServer;
import javax.management.ObjectName;
public class Main {
public static void main(String[] args) throws Exception {

MBeanServer mbs = ManagementFactory.getPlatformMBeanServer(); //1
ObjectName name = new ObjectName("com.example.mbeans:type=Hello");
Hello mbean = new Hello();
mbs.registerMBean(mbean, name); //2
System.out.println("Waiting forever..."); //3
Thread.sleep(Long.MAX_VALUE);
}
}


其中 //1 是获得平台platformMBeanServer, JVisualVM会连接到这个MBeanServer,当然也可以通过MBeanServerFactory来创建自己的MBeanServer。
//2 注册MBean
//3 main thread进入sleep状态,RMI connector server应该是有一个新的线程

* 客户端实现
package org.jmx;

import javax.management.MBeanServerConnection;
import javax.management.ObjectName;
import javax.management.remote.JMXConnector;
import javax.management.remote.JMXConnectorFactory;
import javax.management.remote.JMXServiceURL;

public class MyJConsole {
public static void main(String args[]) {
try {
// "jmxrmi" is the default service name registered by PlatformMBeanServer, which can connected
// by JVisualVM and JConsole directly.
JMXServiceURL url = new JMXServiceURL(
"service:jmx:rmi:///jndi/rmi://localhost:4949/jmxrmi"); //1
JMXConnector jmxc = JMXConnectorFactory.connect(url, null);
MBeanServerConnection mbsc = jmxc.getMBeanServerConnection();

// register a listener
System.out.println("Register a remote listener.");
ObjectName name = new ObjectName("com.example.mbeans:type=Hello");
mbsc.addNotificationListener(name, new HelloListener(), null, null); //2

System.out.println("Waiting forever...");
Thread.sleep(Long.MAX_VALUE);
} catch (Exception e) {
e.printStackTrace();
}
}
}


//1 实例化一个JMXServiceURL , 这个url的格式可以参考JMXServiceURL 的javadoc。
//2 注册客户端listener到远程MBeanServer。 注意所有的类如果实现了Remote和NotificationListener接口,那么在远程传输的时候是传引用而不是值,所以这里listener的逻辑都会在client执行,不是在server端执行。

* client listener
package org.jmx;

import javax.management.AttributeChangeNotification;
import javax.management.Notification;
import javax.management.NotificationListener;

public class HelloListener implements NotificationListener {

@Override
public void handleNotification(Notification notification, Object handback) {
if (notification instanceof AttributeChangeNotification){
AttributeChangeNotification attNotification = (AttributeChangeNotification)notification;
System.out.println("change CacheSize from " + attNotification.getOldValue()
+ " to " + attNotification.getNewValue());
}
else {
System.out.println(notification);
}
}
}


开始执行这些代码。
1) 启动server端
>> java -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.port=4949 -Dcom.sun.management.jmxremote.ssl=false -Djava.rmi.server.hostname=10.40.0.101
-Dcom.sun.management.jmxremote.authenticate=false org.jmx.Main (还有制定classpath一类的)
* 注意这里的-Djava.rmi.server.hostname=10.40.0.101, 实际上client跑在32bit的win7操作系统上,而server是64bit的linux操作系统, 如果不指定这个属性来绑定4949端口到network interface 10.40.0.101上,那么client可能无法连接到server。 因为client的机器配置为只能访问server的内网ip(10.40.0.101),所以必须绑定server端的VM在10.40.0.101上监听4949端口。
Waiting forever...

2)启动客户端
>> java org.jmx.MyJConsole
Register a remote listener.
Waiting forever...

3) 启动JVisualVM,从左边窗口可以看到一个‘Local’节点,右键点击,选择‘add JMX connection’, 在conntion中输入‘service:jmx:rmi:///jndi/rmi://localhost:4949/jmxrmi’。你会看到
新建的这个节点,双击来展开右边的tab pane, 选择‘MBeans,然后你就可以看到自己注册的MBean ’com.example.mbeans:type=Hello‘。 双击节点’Hello‘,在右边选择’Attributes‘ ,并且编辑’cacheSize‘的值为444。
然后来检查server和client的控制台有什么输出。
Server: Cache size now 444
Client: change CacheSize from 333 to 444


怎么样? 还是很值得在项目中采用JMX的吧!


Now I finished a example which use Spring to expose JMX to JvisualVM, my test environment: tomcat7.0.29 + spring2.5.6
1) Define Spring in web.xml:

xmlns="http://java.sun.com/xml/ns/javaee" xmlns:web="http://java.sun.com/xml/ns/javaee/web-app_2_5.xsd"
xsi:schemaLocation="http://java.sun.com/xml/ns/javaee http://java.sun.com/xml/ns/javaee/web-app_3_0.xsd"
id="WebApp_ID" version="3.0">

Tomcat7





contextConfigLocation
classpath:spring-service.xml



org.springframework.web.context.ContextLoaderListener



2) Implement a simple POJO:
package org.tomcat7;

public class HelloBean {
private int age;
private String name;

public int getAge() {
return age;
}

public void setAge(int age) {
this.age = age;
}

public String getName() {
return name;
}

public void setName(String name) {
this.name = name;
}

public void append(String suffix) {
this.name += suffix;
}
}

3) Export HelloBean by Spring(spring-service.xml):

xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:p="http://www.springframework.org/schema/p"
xmlns:aop="http://www.springframework.org/schema/aop" xmlns:context="http://www.springframework.org/schema/context"
xmlns:jee="http://www.springframework.org/schema/jee" xmlns:tx="http://www.springframework.org/schema/tx"
xsi:schemaLocation="
http://www.springframework.org/schema/aop http://www.springframework.org/schema/aop/spring-aop-2.5.xsd
http://www.springframework.org/schema/beans http://www.springframework.org/schema/beans/spring-beans-2.5.xsd
http://www.springframework.org/schema/context http://www.springframework.org/schema/context/spring-context-2.5.xsd
http://www.springframework.org/schema/jee http://www.springframework.org/schema/jee/spring-jee-2.5.xsd
http://www.springframework.org/schema/tx http://www.springframework.org/schema/tx/spring-tx-2.5.xsd">


lazy-init="false">













4) Deploy web application to tomcat and launch it.
NOTE: modify catelina.sh to enable remote JMX connection(-Dcom.sun.management.jmxremote.port=3333 -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.authenticate=false )

5) Start JvisualVM, and connect to localhost:3333.
Now from 'MBean' tab, you will find our HelloBean, then you can moniter states and invoke operations of it.

Wednesday, February 24, 2010

The flush mode and behaviour of Hibernate

A few days ago, I found some strange problem from TE's log. There is a service names 'sell ticket', which implement below logic,I will present them in pseudocode.
  1. TransactionDao.getByDevAndTraceMessageId(X,Y)
  2. TransactionDao.insert(trans)
  3. SettlementReportDao.getByOperatorAndBatchNoAndMerchant(X,Y,Z)
  4. GameInstanceDao.getByGameIdAndDrawNo(X,Y)
  5. MerchantDao.update(X) //1
  6. MerchantDao.update(Y) //2
  7. TicketDao.insert(X)
  8. LottoEntryDao.insert(X) //1
  9. LottoEntryDao.insert(Y) //2
  10. LottoEntryDao.insert(Z) //3
  11. print log 'finish saving entries'
  12. TransactionDao.update(trans)
  13. commit transaction.
  14. print log 'Start to sync transaction log'
Some long transaction spend about 30 seconds from stop#11 to step#14. As my understanding, from step#11 to step#14 only update te_transaction and then commit transaction, why take so long time?
I have below two considerations:
  1. when update transaction, this transaction is blocked.
  2. when commit transaction, it will cost much
For point#1, it should not be blocked, cause at step#2, this transaction should already captured the lock. For point#2, if all sql statements have been sent to database, then committing should be very quick.
Why?

I understand hibernate in a wrong way which cause I get wrong conclusion. Let's think about the flush behaviour of hibernate. Each time when we call a Dao to insert,update,delete a entry, it won't hit database immediately, hibernate will record these actions, update entity states. When do flush, hiberate will send all these sql to database. Remember below points:
  • A select statement will always hit database to retrieve latest data from database, and update the related entity in cache(it should be 2nd level cache, which is managed by hibernate, so hibernate runtime is responsible for ensuring that all updates to the state of all entities in the persistence context which could potentially affect the result of the query are visible to the processing of the query.
     ..actually it isn't always true, there are 2 exceptions. #1)Query entity by id(entity identifier). for example if insert a entity first, then query that entity by ID, hibernate won't hit the underlying database, as the inserted entity is completedly managed by hibernate runtime. #2)If insert a entity, and then query that entity from outside of hibernate runtime, such as direct JDBC. In this case, as hibernate runtime has no awareness of the querying, it won't flush the insert/update/delete SQL to underlying database. ).
  • When execute a select query, hibernate will check if some previous actions(save, update,delete) have changed the status of queried entity(if changed, hibernate marked it as dirty). If so, hibernate will flush all update actions of entity to underlying database.
  • Hibernate will organize all actions into 'insert', 'update','delete' category. When do flushing, hibernate will perform all actions in order 'insert', 'update', 'delete'. It means maybe you invoke a update method before a insert, but in fact, insert will be performed first.
Then what is flush? when hibernate will flush? Flush will sync the entity state between hibernate cache and database. In case of below condition, hibernate will perform flush(We are talking about FlushMode.AUTO).
  • Before select, and some previous actions have changed the queried entity state. Image it, if a transaction query a entity(E1), then change some fields(E2), then query this entity again. As query will always hit database, if doesn't flush, this query will get E1. Obviously it is incorrect, that is why hibernate will perform flush before the second query.
  • Before committing transaction.
  • Manualy invoke flush() method.
....

"When execute a select enquiry, hibernate will check if some previous actions(save, update,delete) will change the status of queried entity." I will further explain what does this statement means. Lets say there are 2 entities: WorkingKey and Payout(these 2 entities have no any relationship), and:
1) insert a new Payout entity
2) query WorkingKey by some criteria
3) commit transaction.
The test code as below:
@Test
public void testHibernateFlush() throws Exception{
  Payout p = DomainMocker.mockPayout();
  p.getTransaction().setId("TRANS-8111");
  logger.debug("before insert payout...");
  this.getPayoutDao().insert(p);
  logger.debug("before querying working key...");
  this.getWorkingKeyDao().getWorkingKey("20101216", "GPE-111");
  this.setComplete();
}
Ok, what will be printed out? -------------
[2011-01-17 15:39:08,984][main][DEBUG][BaseTransactionTest] before insert payout...
[2011-01-17 15:39:09,046][main][DEBUG][BaseTransactionTest] before querying working key...
[2011-01-17 15:39:09,359][main][INFO ][sqltiming] select workingkey0_.ID as ID24_, workingkey0_.CREATE_TIME as CREATE2_24_, workingkey0_.UPDATE_TIME as UPDATE3_24_, workingkey0_.VERSION as VERSION24_, workingkey0_.CREATE_DATE as CREATE5_24_, workingkey0_.DATA_KEY as DATA6_24_, workingkey0_.GPE_ID as GPE7_24_, workingkey0_.MAC_KEY as MAC8_24_ from GPE_KEY workingkey0_ where workingkey0_.CREATE_DATE='20101216' and workingkey0_.GPE_ID='GPE-111' {executed in 0 msec}
[2011-01-17 15:39:09,375][main][INFO ][sqltiming] insert into PAYOUT (CREATE_TIME, UPDATE_TIME, VERSION, TOTAL_AMOUNT_B4_TAX, DEV_ID, GAME_INSTANCE_ID, IS_BY_MANUAL, IS_VALID, MERCHANT_ID, OPERATOR_ID, SETTLEMENT_FLAG, SETTLEMENT_TIME, STATUS, TICKET_SERIALNO, TOTAL_AMOUNT, TRANSACTION_ID, TYPE, ID) values (2011-01-17 15:39:08.984, 2011-01-17 15:39:08.984, 0, NULL, 0, 'GII-111', 0, 1, 0, NULL, NULL, NULL, 0, '123456', 1245.01, 'TRANS-8111', 1, '97d660a332774c5fa8a434aa9a18c0bf'[BR] {executed in 16 msec}
[2011-01-17 15:39:09,375][main][DEBUG][WorkingKeyDaoImplTest] Committed transaction after execution of test [testHibernateFlush].
-------------
Surprise! You will see 'insert payout...' was executed after 'select workingkey...'. Why? yes, it is due to 'insert Payout' won't change the state of entity 'Workingkey'.

Flush in Spring test framework
I wrote a testcase extending from Spring AbstractTransactionalDataSourceSpringContextTests, by spring test framework, the transaction will be rollbacked automatically when finish testcase.
@Test
 /** the persistence technology is JPA(hibernate) */
public void testInsert() {
int init_countOfSP = this.countRowsInTable("RA_TE_TICKET_SCHEMA");
int init_countOfEntry = this.countRowsInTable("RA_TE_ENTRY");
     // generate a SalePackage instance which map to table 'RA_TE_TICKET_SCHEMA'
SalePackage sp = mock();
this.getSalePackageDao().insert(sp); int countOfSP = this.countRowsInTable("RA_TE_TICKET_SCHEMA");
int countOfEntry = this.countRowsInTable("RA_TE_ENTRY");
assertEquals(init_countOfSP + 1, countOfSP);
assertEquals(init_countOfEntry + 3, countOfEntry);
}
As my understanding, when countRowsInTable("RA_TE_TICKET_SCHEMA") (the underlying SQL is 'select count(0) from RA_TE_TICKET_SCHEMA) hibernate will issue a 'insert salepackage...' to database....but actual result is no any 'insert...' SQL...why??
It is due to countRowsInTable("RA_TE_TICKET_SCHEMA") is executed from jdbcTemplate(spring + jdbc), JPA implementation has no information of countRowsInTable. Finaly this test case will fail, as no salepackage is inserted into database.

Select will always trigger flush??
Continue with above testcase. As countRowsInTable is executed by JDBC directly, i changed my testcase as below:
@Test
public void testInsert() {
int init_countOfSP = this.countRowsInTable("RA_TE_TICKET_SCHEMA");
int init_countOfEntry = this.countRowsInTable("RA_TE_ENTRY");
SalePackage sp = mock();
this.getSalePackageDao().insert(sp);
sp = this.getSalePackageDao().findById(SalePackage.class, sp.getId());
assertNotNull(sp);
int countOfSP = this.countRowsInTable("RA_TE_TICKET_SCHEMA"); int countOfEntry = this.countRowsInTable("RA_TE_ENTRY");
assertEquals(init_countOfSP + 1, countOfSP);
assertEquals(init_countOfEntry + 3, countOfEntry);
}
I will query SalePackage immediately after insert, and the implementation of findById:
public T findById(Class clazz, String id){ 
return this.getJpaTemplate().find(clazz, id);
}
The testcase failed again...why? I think it is caused by this.getJpaTemplate().find(clazz, id);. As JPA implementation(hibernate) has its own cache, when findById hibernate will find this entity from its cache, no need to hit database, and the most important is hibernate knows that Entity with id(sp.getid()) is inserted in current transaction, it means no other transactions can see this entity. So hibernate even no need to issue a 'select...' SQL to database, it will retrieve this entity from its local cache directly.
But how about if we implement findById() like this:
public T findById(Class clazz, String id){ 
List sp = this.getJpaTemplate().find("from SalePackage p where p.id='" + id + "'");
if (sp.size() > 0) return (T)sp.get(0);
return null;
}
The test result is hibernate will issue two SQLs: 'insert salepackage...' and 'select ...with id=..'. As when you call this.getJpaTemplate().find(clazz, id), JPA runtime definitely know that you are query entity by identifier, while if this.getJpaTemplate().find("from SalePackage p where p.id='" + id + "'") hibernate runtime doesn't know it :).

Reference
Wow, I found a nice post about hibernate flush, "http://blog.krecan.net/2008/01/05/flushing-hibernate/"