如何知道Hibernate已经成功运用了二级缓存Ehcache

    我按照一般的方法运用了Ehcache作为Hibernate的二级缓存
         <property name="cache.provider_class">
            org.hibernate.cache.EhCacheProvider
        </property>
   CLASSPATH下也有了配置过的EHCACHE.XML文件
    但是在运行中程序没有任何变化，不知道是否运用了，望

最好的办法，就是，debug!
其次是打出日志！
最后就是，看效果！

    问题是DEBUG之后我也不清楚应该看哪里！
     DEBUG的信息实在是太多，很难看全！
能否给个实例，指出那里显示了使用了二级缓存！

你的hbm里面映射文件有配cache麽？

    终于发现原因了，因为的TUser类中有个one-to-one的对应TPassport
所以必须在TPassport中也加入<cache usage="">才能使二级缓存在TUser类
身上有效

意思是说有关联的类必须都纳入二级缓存？
有一个关联类没有设置缓存，则所有相关类都不会缓存？

对Log4J进行分类分级一下，我的如下，你可以进行修改：

log4j.threshold = ALL
log4j.rootLogger = ALL
#
log4j.category.org.springframework debug,FrameWorkSpring
log4j.category.org.hibernate debug,FrameWorkHibernate
log4j.category.net.sf.ehcache debug,FrameWorkEhCache

log4j.appender.FrameWorkSpring org.apache.log4j.DailyRollingFileAppender
log4j.appender.FrameWorkSpring.File ${system.logPath}/FrameWorkSpring.log
log4j.appender.FrameWorkSpring.DatePattern yyyy-MM-dd'.log'
log4j.appender.FrameWorkSpring.layout org.apache.log4j.PatternLayout
log4j.appender.FrameWorkSpring.layout.ConversionPattern [%c]-[%p] %m%n
log4j.appender.FrameWorkSpring.append false

log4j.appender.FrameWorkHibernate org.apache.log4j.DailyRollingFileAppender
log4j.appender.FrameWorkHibernate.File ${system.logPath}/FrameWorkHibernate.log
log4j.appender.FrameWorkHibernate.DatePattern yyyy-MM-dd'.log'
log4j.appender.FrameWorkHibernate.layout org.apache.log4j.PatternLayout
log4j.appender.FrameWorkHibernate.layout.ConversionPattern [%c]-[%p] %m%n
log4j.appender.FrameWorkHibernate.append false

log4j.appender.FrameWorkEhCache org.apache.log4j.DailyRollingFileAppender
log4j.appender.FrameWorkEhCache.File ${system.logPath}/FrameWorkEhCache.log
log4j.appender.FrameWorkEhCache.DatePattern yyyy-MM-dd'.log'
log4j.appender.FrameWorkEhCache.layout org.apache.log4j.PatternLayout
log4j.appender.FrameWorkEhCache.layout.ConversionPattern [%c]-[%p] %m%n
log4j.appender.FrameWorkEhCache.append false

可以看到命中的信息
[net.sf.ehcache.store.MemoryStore]-[DEBUG] xxx.xxx.XyzCache: xxx.xxx.XyzMemoryStore hit for xxx.xxx.Xyz#8

没命中的信息：
[net.sf.ehcache.Cache]-[DEBUG] xxx.xxx.Xyz cache - Miss

大概是这样子的，可以继续进行观察它的详细log信息再做分析。

如果你在ehcache.xml中没有明确设置对每个实体的缓存设置。在应用启动的时候会有很多的Warn(基本上是每个实体一个）提示你将使用默认的缓存策略。
还有就是可以在刚启动后去访问某些查询量大的页面，在第一次打开后再刷新可以明显看到查询的ＳＱＬ变少了。

15:57:49,561  INFO Environment:479 - Hibernate 3.1.3
15:57:49,611  INFO Environment:509 - hibernate.properties not found
15:57:49,621  INFO Environment:525 - using CGLIB reflection optimizer
15:57:49,631  INFO Environment:555 - using JDK 1.4 java.sql.Timestamp handling
15:57:50,001  INFO Configuration:1308 - configuring from resource: /hibernate.cfg.xml
15:57:50,001  INFO Configuration:1285 - Configuration resource: /hibernate.cfg.xml
15:57:50,312 DEBUG DTDEntityResolver:22 - trying to resolve system-id [http://hibernate.sourceforge.net/hibernate-configuration-3.0.dtd]
15:57:50,312 DEBUG DTDEntityResolver:24 - recognized hibernate namespace; attempting to resolve on classpath under org/hibernate/
15:57:50,352 DEBUG DTDEntityResolver:34 - located [http://hibernate.sourceforge.net/hibernate-configuration-3.0.dtd] in classpath
15:57:50,542 DEBUG Configuration:1269 - show_sql=true
15:57:50,542 DEBUG Configuration:1269 - myeclipse.connection.profile=TestMySql
15:57:50,552 DEBUG Configuration:1269 - connection.url=jdbc:mysql://localhost:3306/mydb?characterEncoding=ISO-8859-1
15:57:50,552 DEBUG Configuration:1269 - connection.username=root
15:57:50,552 DEBUG Configuration:1269 - connection.password=root
15:57:50,552 DEBUG Configuration:1269 - connection.driver_class=com.mysql.jdbc.Driver
15:57:50,552 DEBUG Configuration:1269 - dialect=org.hibernate.dialect.MySQLDialect
15:57:50,562 DEBUG Configuration:1269 - hibernate.cache.provider_class=net.sf.ehcache.hibernate.EhCacheProvider
15:57:50,562 DEBUG Configuration:1269 - net.sf.ehcache.configurationResourceName=ehcache.xml
15:57:50,562 DEBUG Configuration:1464 - foo<-org.dom4j.tree.DefaultAttribute@276af2 [Attribute: name resource value "test/ehcache/hibernateUse/Student.hbm.xml"]
15:57:50,572  INFO Configuration:469 - Reading mappings from resource: test/ehcache/hibernateUse/Student.hbm.xml
15:57:50,592 DEBUG DTDEntityResolver:22 - trying to resolve system-id [http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd]
15:57:50,592 DEBUG DTDEntityResolver:24 - recognized hibernate namespace; attempting to resolve on classpath under org/hibernate/
15:57:50,592 DEBUG DTDEntityResolver:34 - located [http://hibernate.sourceforge.net/hibernate-mapping-3.0.dtd] in classpath
15:57:51,233  INFO HbmBinder:309 - Mapping class: test.ehcache.hibernateUse.Student -> student
15:57:51,263 DEBUG HbmBinder:1261 - Mapped property: id -> id
15:57:51,333 DEBUG HbmBinder:1261 - Mapped property: name -> name
15:57:51,333  INFO Configuration:1419 - Configured SessionFactory: foo
15:57:51,333 DEBUG Configuration:1420 - properties: {hibernate.connection.password=root, java.runtime.name=Java(TM) 2 Runtime Environment, Standard Edition, hibernate.cache.provider_class=net.sf.ehcache.hibernate.EhCacheProvider, sun.boot.library.path=D:\jdk1.5.0_05\jre\bin, java.vm.version=1.5.0_05-b05, net.sf.ehcache.configurationResourceName=ehcache.xml, hibernate.connection.username=root, java.vm.vendor=Sun Microsystems Inc., java.vendor.url=http://java.sun.com/, path.separator=;, java.vm.name=Java HotSpot(TM) Client VM, file.encoding.pkg=sun.io, user.country=CN, sun.os.patch.level=Service Pack 2, java.vm.specification.name=Java Virtual Machine Specification, user.dir=D:\myjava\TestEhCache, java.runtime.version=1.5.0_05-b05, java.awt.graphicsenv=sun.awt.Win32GraphicsEnvironment, java.endorsed.dirs=D:\jdk1.5.0_05\jre\lib\endorsed, os.arch=x86, java.io.tmpdir=C:\DOCUME~1\xiaowei\LOCALS~1\Temp\, line.separator=
, java.vm.specification.vendor=Sun Microsystems Inc., user.variant=, os.name=Windows XP, sun.jnu.encoding=GBK, hibernate.net.sf.ehcache.configurationResourceName=ehcache.xml, java.library.path=D:\jdk1.5.0_05\bin;.;C:\WINDOWS\system32;C:\WINDOWS;.;D:\jdk1.5.0_05\bin;D:\Middlegen-Hibernate-r5\bin;D:\apache-ant-1.6.5\bin;D:\jakarta-tomcat-5.0.30\bin;C:\WINDOWS\system32;C:\WINDOWS;C:\WINDOWS\System32\Wbem;D:\Program Files\MySQL\MySQL Server 5.0\bin;D:\apache-ant-1.6.5\bin;C:\Program Files\Subversion\bin, hibernate.myeclipse.connection.profile=TestMySql, java.specification.name=Java Platform API Specification, java.class.version=49.0, sun.management.compiler=HotSpot Client Compiler, os.version=5.1, connection.password=root, user.home=C:\Documents and Settings\xiaowei, user.timezone=Asia/Shanghai, connection.username=root, java.awt.printerjob=sun.awt.windows.WPrinterJob, file.encoding=GBK, java.specification.version=1.5, hibernate.connection.driver_class=com.mysql.jdbc.Driver, myeclipse.connection.profile=TestMySql, show_sql=true, user.name=xiaowei, java.class.path=D:\myjava\TestEhCache\bin;D:\myjava\TestEhCache\lib\junit-3.8.1.jar;D:\myjava\TestEhCache\lib\mysql-connector-java-5.0.4-bin.jar;D:\myjava\TestEhCache\lib\commons-lang-1.0.1.jar;D:\myjava\TestEhCache\lib\log4j-1.2.11.jar;D:\myjava\TestEhCache\lib\dom4j-1.4.jar;D:\myjava\TestEhCache\lib\commons-collections-2.1.1.jar;D:\myjava\TestEhCache\lib\commons-logging-1.0.4.jar;D:\myjava\TestEhCache\lib\hibernate3.jar;D:\myjava\TestEhCache\lib\ehcache-1.2.4.jar;D:\myjava\TestEhCache\lib\jta.jar;D:\myjava\TestEhCache\lib\cglib-2.1.3.jar;D:\myjava\TestEhCache\lib\asm.jar, hibernate.show_sql=true, java.vm.specification.version=1.0, java.home=D:\jdk1.5.0_05\jre, sun.arch.data.model=32, hibernate.dialect=org.hibernate.dialect.MySQLDialect, hibernate.connection.url=jdbc:mysql://localhost:3306/mydb?characterEncoding=ISO-8859-1, user.language=zh, java.specification.vendor=Sun Microsystems Inc., awt.toolkit=sun.awt.windows.WToolkit, hibernate.cglib.use_reflection_optimizer=true, java.vm.info=mixed mode, sharing, java.version=1.5.0_05, java.ext.dirs=D:\jdk1.5.0_05\jre\lib\ext, sun.boot.class.path=D:\jdk1.5.0_05\jre\lib\rt.jar;D:\jdk1.5.0_05\jre\lib\i18n.jar;D:\jdk1.5.0_05\jre\lib\sunrsasign.jar;D:\jdk1.5.0_05\jre\lib\jsse.jar;D:\jdk1.5.0_05\jre\lib\jce.jar;D:\jdk1.5.0_05\jre\lib\charsets.jar;D:\jdk1.5.0_05\jre\classes, java.vendor=Sun Microsystems Inc., connection.driver_class=com.mysql.jdbc.Driver, file.separator=\, hibernate.session_factory_name=foo, java.vendor.url.bug=http://java.sun.com/cgi-bin/bugreport.cgi, sun.io.unicode.encoding=UnicodeLittle, sun.cpu.endian=little, sun.desktop=windows, connection.url=jdbc:mysql://localhost:3306/mydb?characterEncoding=ISO-8859-1, dialect=org.hibernate.dialect.MySQLDialect, sun.cpu.isalist=pentium_pro+mmx pentium_pro pentium+mmx pentium i486 i386 i86}
15:57:51,333 DEBUG Configuration:1167 - Preparing to build session factory with filters : {}
15:57:51,343 DEBUG Configuration:1002 - processing extends queue
15:57:51,343 DEBUG Configuration:1006 - processing collection mappings
15:57:51,343 DEBUG Configuration:1017 - processing native query and ResultSetMapping mappings
15:57:51,343 DEBUG Configuration:1025 - processing association property references
15:57:51,343 DEBUG Configuration:1047 - processing foreign key constraints
15:57:51,734  INFO DriverManagerConnectionProvider:41 - Using Hibernate built-in connection pool (not for production use!)
15:57:51,754  INFO DriverManagerConnectionProvider:42 - Hibernate connection pool size: 20
15:57:51,754  INFO DriverManagerConnectionProvider:45 - autocommit mode: false
15:57:51,794  INFO DriverManagerConnectionProvider:80 - using driver: com.mysql.jdbc.Driver at URL: jdbc:mysql://localhost:3306/mydb?characterEncoding=ISO-8859-1
15:57:51,794  INFO DriverManagerConnectionProvider:83 - connection properties: {user=root, password=root}
15:57:51,794 DEBUG DriverManagerConnectionProvider:93 - total checked-out connections: 0
15:57:51,794 DEBUG DriverManagerConnectionProvider:109 - opening new JDBC connection
15:57:52,605 DEBUG DriverManagerConnectionProvider:115 - created connection to: jdbc:mysql://localhost:3306/mydb?characterEncoding=ISO-8859-1, Isolation Level: 4
15:57:52,605  INFO SettingsFactory:77 - RDBMS: MySQL, version: 5.0.18-nt
15:57:52,605  INFO SettingsFactory:78 - JDBC driver: MySQL-AB JDBC Driver, version: mysql-connector-java-5.0.4 ( $Date: 2006-10-19 17:47:48 +0200 (Thu, 19 Oct 2006) $, $Revision: 5908 $ )
15:57:52,615 DEBUG DriverManagerConnectionProvider:129 - returning connection to pool, pool size: 1
15:57:52,725  INFO Dialect:103 - Using dialect: org.hibernate.dialect.MySQLDialect
15:57:52,755  INFO TransactionFactoryFactory:31 - Using default transaction strategy (direct JDBC transactions)
15:57:52,765  INFO TransactionManagerLookupFactory:33 - No TransactionManagerLookup configured (in JTA environment, use of read-write or transactional second-level cache is not recommended)
15:57:52,775  INFO SettingsFactory:125 - Automatic flush during beforeCompletion(): disabled
15:57:52,775  INFO SettingsFactory:129 - Automatic session close at end of transaction: disabled
15:57:52,795  INFO SettingsFactory:136 - JDBC batch size: 15
15:57:52,795  INFO SettingsFactory:139 - JDBC batch updates for versioned data: disabled
15:57:52,795  INFO SettingsFactory:144 - Scrollable result sets: enabled
15:57:52,795 DEBUG SettingsFactory:148 - Wrap result sets: disabled
15:57:52,795  INFO SettingsFactory:152 - JDBC3 getGeneratedKeys(): enabled
15:57:52,795  INFO SettingsFactory:160 - Connection release mode: auto
15:57:52,805  INFO SettingsFactory:184 - Maximum outer join fetch depth: 2
15:57:53,036  INFO SettingsFactory:187 - Default batch fetch size: 1
15:57:53,036  INFO SettingsFactory:191 - Generate SQL with comments: disabled
15:57:53,036  INFO SettingsFactory:195 - Order SQL updates by primary key: disabled
15:57:53,036  INFO SettingsFactory:338 - Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory
15:57:53,116  INFO ASTQueryTranslatorFactory:24 - Using ASTQueryTranslatorFactory
15:57:53,116  INFO SettingsFactory:203 - Query language substitutions: {}
15:57:53,116  INFO SettingsFactory:209 - Second-level cache: enabled
15:57:53,116  INFO SettingsFactory:213 - Query cache: disabled
15:57:53,126  INFO SettingsFactory:325 - Cache provider: net.sf.ehcache.hibernate.EhCacheProvider
15:57:53,156  INFO SettingsFactory:228 - Optimize cache for minimal puts: disabled
15:57:53,156  INFO SettingsFactory:237 - Structured second-level cache entries: disabled
15:57:53,156 DEBUG SQLExceptionConverterFactory:52 - Using dialect defined converter
15:57:53,186  INFO SettingsFactory:257 - Echoing all SQL to stdout
15:57:53,186  INFO SettingsFactory:264 - Statistics: disabled
15:57:53,186  INFO SettingsFactory:268 - Deleted entity synthetic identifier rollback: disabled
15:57:53,196  INFO SettingsFactory:283 - Default entity-mode: pojo
15:57:53,346  INFO SessionFactoryImpl:154 - building session factory
15:57:53,346 DEBUG SessionFactoryImpl:165 - Session factory constructed with filter configurations : {}
15:57:53,346 DEBUG SessionFactoryImpl:168 - instantiating session factory with properties: {java.runtime.name=Java(TM) 2 Runtime Environment, Standard Edition, hibernate.connection.password=root, hibernate.cache.provider_class=net.sf.ehcache.hibernate.EhCacheProvider, sun.boot.library.path=D:\jdk1.5.0_05\jre\bin, java.vm.version=1.5.0_05-b05, net.sf.ehcache.configurationResourceName=ehcache.xml, hibernate.connection.username=root, java.vm.vendor=Sun Microsystems Inc., java.vendor.url=http://java.sun.com/, path.separator=;, java.vm.name=Java HotSpot(TM) Client VM, file.encoding.pkg=sun.io, user.country=CN, sun.os.patch.level=Service Pack 2, java.vm.specification.name=Java Virtual Machine Specification, user.dir=D:\myjava\TestEhCache, java.runtime.version=1.5.0_05-b05, java.awt.graphicsenv=sun.awt.Win32GraphicsEnvironment, java.endorsed.dirs=D:\jdk1.5.0_05\jre\lib\endorsed, os.arch=x86, java.io.tmpdir=C:\DOCUME~1\xiaowei\LOCALS~1\Temp\, line.separator=
, java.vm.specification.vendor=Sun Microsystems Inc., user.variant=, os.name=Windows XP, sun.jnu.encoding=GBK, hibernate.net.sf.ehcache.configurationResourceName=ehcache.xml, java.library.path=D:\jdk1.5.0_05\bin;.;C:\WINDOWS\system32;C:\WINDOWS;.;D:\jdk1.5.0_05\bin;D:\Middlegen-Hibernate-r5\bin;D:\apache-ant-1.6.5\bin;D:\jakarta-tomcat-5.0.30\bin;C:\WINDOWS\system32;C:\WINDOWS;C:\WINDOWS\System32\Wbem;D:\Program Files\MySQL\MySQL Server 5.0\bin;D:\apache-ant-1.6.5\bin;C:\Program Files\Subversion\bin, hibernate.myeclipse.connection.profile=TestMySql, java.specification.name=Java Platform API Specification, java.class.version=49.0, sun.management.compiler=HotSpot Client Compiler, os.version=5.1, user.home=C:\Documents and Settings\xiaowei, connection.password=root, user.timezone=Asia/Shanghai, java.awt.printerjob=sun.awt.windows.WPrinterJob, connection.username=root, java.specification.version=1.5, file.encoding=GBK, myeclipse.connection.profile=TestMySql, hibernate.connection.driver_class=com.mysql.jdbc.Driver, show_sql=true, java.class.path=D:\myjava\TestEhCache\bin;D:\myjava\TestEhCache\lib\junit-3.8.1.jar;D:\myjava\TestEhCache\lib\mysql-connector-java-5.0.4-bin.jar;D:\myjava\TestEhCache\lib\commons-lang-1.0.1.jar;D:\myjava\TestEhCache\lib\log4j-1.2.11.jar;D:\myjava\TestEhCache\lib\dom4j-1.4.jar;D:\myjava\TestEhCache\lib\commons-collections-2.1.1.jar;D:\myjava\TestEhCache\lib\commons-logging-1.0.4.jar;D:\myjava\TestEhCache\lib\hibernate3.jar;D:\myjava\TestEhCache\lib\ehcache-1.2.4.jar;D:\myjava\TestEhCache\lib\jta.jar;D:\myjava\TestEhCache\lib\cglib-2.1.3.jar;D:\myjava\TestEhCache\lib\asm.jar, user.name=xiaowei, hibernate.show_sql=true, java.vm.specification.version=1.0, sun.arch.data.model=32, java.home=D:\jdk1.5.0_05\jre, hibernate.connection.url=jdbc:mysql://localhost:3306/mydb?characterEncoding=ISO-8859-1, hibernate.dialect=org.hibernate.dialect.MySQLDialect, java.specification.vendor=Sun Microsystems Inc., user.language=zh, awt.toolkit=sun.awt.windows.WToolkit, java.vm.info=mixed mode, sharing, hibernate.cglib.use_reflection_optimizer=true, java.version=1.5.0_05, java.ext.dirs=D:\jdk1.5.0_05\jre\lib\ext, sun.boot.class.path=D:\jdk1.5.0_05\jre\lib\rt.jar;D:\jdk1.5.0_05\jre\lib\i18n.jar;D:\jdk1.5.0_05\jre\lib\sunrsasign.jar;D:\jdk1.5.0_05\jre\lib\jsse.jar;D:\jdk1.5.0_05\jre\lib\jce.jar;D:\jdk1.5.0_05\jre\lib\charsets.jar;D:\jdk1.5.0_05\jre\classes, java.vendor=Sun Microsystems Inc., file.separator=\, connection.driver_class=com.mysql.jdbc.Driver, hibernate.session_factory_name=foo, java.vendor.url.bug=http://java.sun.com/cgi-bin/bugreport.cgi, sun.cpu.endian=little, sun.io.unicode.encoding=UnicodeLittle, sun.desktop=windows, connection.url=jdbc:mysql://localhost:3306/mydb?characterEncoding=ISO-8859-1, sun.cpu.isalist=pentium_pro+mmx pentium_pro pentium+mmx pentium i486 i386 i86, dialect=org.hibernate.dialect.MySQLDialect}
15:57:53,356 DEBUG EhCacheProvider:133 - prepending / to /ehcache.xml. It should be placed in the rootof the classpath rather than in a package.
15:57:53,356 DEBUG EhCacheProvider:163 - Creating EhCacheProvider from a specified resource: /ehcache.xml Resolved to URL: file:/D:/myjava/TestEhCache/bin/ehcache.xml
15:57:53,406 DEBUG ConfigurationFactory:87 - Configuring ehcache from URL: file:/D:/myjava/TestEhCache/bin/ehcache.xml
15:57:53,416 DEBUG ConfigurationFactory:139 - Configuring ehcache from InputStream
15:57:53,456 DEBUG DiskStoreConfiguration:71 - Disk Store Path: C:\DOCUME~1\xiaowei\LOCALS~1\Temp\
15:57:53,496 DEBUG ConfigurationHelper:208 - No CacheManagerEventListenerFactory class specified. Skipping...
15:57:53,496 DEBUG ConfigurationHelper:183 - No CachePeerListenerFactoryConfiguration specified. Not configuring a CacheManagerPeerListener.
15:57:53,506 DEBUG ConfigurationHelper:159 - No CachePeerProviderFactoryConfiguration specified. Not configuring a CacheManagerPeerProvider.
15:57:53,637 DEBUG ConfigurationHelper:135 - No BootstrapCacheLoaderFactory class specified. Skipping...
15:57:53,637 DEBUG ConfigurationHelper:135 - No BootstrapCacheLoaderFactory class specified. Skipping...
15:57:53,677 DEBUG DiskStore:194 - Deleting data file test.ehcache.hibernateUse.Student.data
15:57:53,707 DEBUG MemoryStore:73 - Initialized net.sf.ehcache.store.LruMemoryStore for test.ehcache.hibernateUse.Student
15:57:53,717 DEBUG LruMemoryStore:71 - test.ehcache.hibernateUse.Student Cache: Using SpoolingLinkedHashMap implementation
15:57:54,057 DEBUG Cache:471 - Initialised cache: test.ehcache.hibernateUse.Student
15:57:54,167 DEBUG CacheFactory:39 - instantiating cache region: test.ehcache.hibernateUse.Student usage strategy: read-write
15:57:55,690 DEBUG AbstractEntityPersister:2447 - Static SQL for entity: test.ehcache.hibernateUse.Student
15:57:55,710 DEBUG AbstractEntityPersister:2449 -  Version select: select id from student where id =?
15:57:55,710 DEBUG AbstractEntityPersister:2450 -  Snapshot select: select student_.id, student_.name as name0_ from student student_ where student_.id=?
15:57:55,710 DEBUG AbstractEntityPersister:2452 -  Insert 0: insert into student (name, id) values (?, ?)
15:57:55,710 DEBUG AbstractEntityPersister:2453 -  Update 0: update student set name=? where id=?
15:57:55,710 DEBUG AbstractEntityPersister:2454 -  Delete 0: delete from student where id=?
15:57:55,840 DEBUG EntityLoader:79 - Static select for entity test.ehcache.hibernateUse.Student: select student0_.id as id0_0_, student0_.name as name0_0_ from student student0_ where student0_.id=?
15:57:55,850 DEBUG EntityLoader:79 - Static select for entity test.ehcache.hibernateUse.Student: select student0_.id as id0_0_, student0_.name as name0_0_ from student student0_ where student0_.id=?
15:57:55,850 DEBUG EntityLoader:79 - Static select for entity test.ehcache.hibernateUse.Student: select student0_.id as id0_0_, student0_.name as name0_0_ from student student0_ where student0_.id=? for update
15:57:55,870 DEBUG EntityLoader:79 - Static select for entity test.ehcache.hibernateUse.Student: select student0_.id as id0_0_, student0_.name as name0_0_ from student student0_ where student0_.id=? for update
15:57:55,940 DEBUG EntityLoader:34 - Static select for action ACTION_MERGE on entity test.ehcache.hibernateUse.Student: select student0_.id as id0_0_, student0_.name as name0_0_ from student student0_ where student0_.id=?
15:57:55,950 DEBUG EntityLoader:34 - Static select for action ACTION_REFRESH on entity test.ehcache.hibernateUse.Student: select student0_.id as id0_0_, student0_.name as name0_0_ from student student0_ where student0_.id=?
15:57:55,960 DEBUG SessionFactoryObjectFactory:39 - initializing class SessionFactoryObjectFactory
15:57:55,970 DEBUG SessionFactoryObjectFactory:76 - registered: 402883f80fcd3708010fcd37136e0000 (foo)
15:57:55,970  INFO SessionFactoryObjectFactory:86 - Factory name: foo
15:57:55,980  INFO NamingHelper:26 - JNDI InitialContext properties:{}
15:57:55,990 DEBUG NamingHelper:48 - binding: foo
15:57:56,020  WARN SessionFactoryObjectFactory:98 - Could not bind factory to JNDI
javax.naming.NoInitialContextException: Need to specify class name in environment or system property, or as an applet parameter, or in an application resource file:  java.naming.factory.initial
at javax.naming.spi.NamingManager.getInitialContext(Unknown Source)
at javax.naming.InitialContext.getDefaultInitCtx(Unknown Source)
at javax.naming.InitialContext.getURLOrDefaultInitCtx(Unknown Source)
at javax.naming.InitialContext.getNameParser(Unknown Source)
at org.hibernate.util.NamingHelper.bind(NamingHelper.java:52)
at org.hibernate.impl.SessionFactoryObjectFactory.addInstance(SessionFactoryObjectFactory.java:90)
at org.hibernate.impl.SessionFactoryImpl.<init>(SessionFactoryImpl.java:291)
at org.hibernate.cfg.Configuration.buildSessionFactory(Configuration.java:1176)
at test.ehcache.hibernateUse.TestHibernateUse.main(TestHibernateUse.java:18)
15:57:56,050 DEBUG SessionFactoryImpl:293 - instantiated session factory
15:57:56,050 DEBUG SessionFactoryImpl:354 - Checking 0 named HQL queries
15:57:56,050 DEBUG SessionFactoryImpl:374 - Checking 0 named SQL queries
15:57:56,270 DEBUG SessionImpl:219 - opened session at timestamp: 4781584695500800
15:57:56,280 DEBUG JDBCTransaction:54 - begin
15:57:56,290 DEBUG ConnectionManager:415 - opening JDBC connection
15:57:56,290 DEBUG DriverManagerConnectionProvider:93 - total checked-out connections: 0
15:57:56,290 DEBUG DriverManagerConnectionProvider:99 - using pooled JDBC connection, pool size: 0
15:57:56,290 DEBUG JDBCTransaction:59 - current autocommit status: false
15:57:56,290 DEBUG JDBCContext:194 - after transaction begin
15:57:56,320 DEBUG DefaultSaveOrUpdateEventListener:161 - saving transient instance
15:57:56,320 DEBUG IncrementGenerator:80 - fetching initial value: select max(id) from student
15:57:56,320 DEBUG AbstractBatcher:311 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
15:57:56,320 DEBUG SQL:346 - select max(id) from student
Hibernate: select max(id) from student
15:57:56,320 DEBUG AbstractBatcher:424 - preparing statement
15:57:56,381 DEBUG IncrementGenerator:95 - first free id: 3
15:57:56,381 DEBUG AbstractBatcher:319 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
15:57:56,381 DEBUG AbstractBatcher:470 - closing statement
15:57:56,391 DEBUG AbstractSaveEventListener:106 - generated identifier: 3, using strategy: org.hibernate.id.IncrementGenerator
15:57:56,391 DEBUG AbstractSaveEventListener:139 - saving [test.ehcache.hibernateUse.Student#3]
15:57:56,471 DEBUG DefaultSaveOrUpdateEventListener:105 - ignoring persistent instance
15:57:56,471 DEBUG DefaultSaveOrUpdateEventListener:142 - object already associated with session: [test.ehcache.hibernateUse.Student#3]
15:57:56,471 DEBUG DefaultSaveOrUpdateEventListener:105 - ignoring persistent instance
15:57:56,471 DEBUG DefaultSaveOrUpdateEventListener:142 - object already associated with session: [test.ehcache.hibernateUse.Student#3]
15:57:56,471 DEBUG JDBCTransaction:103 - commit
15:57:56,471 DEBUG SessionImpl:332 - automatically flushing session
15:57:56,481 DEBUG AbstractFlushingEventListener:58 - flushing session
15:57:56,481 DEBUG AbstractFlushingEventListener:111 - processing flush-time cascades
15:57:56,481 DEBUG AbstractFlushingEventListener:153 - dirty checking collections
15:57:56,491 DEBUG AbstractFlushingEventListener:170 - Flushing entities and processing referenced collections
15:57:56,521 DEBUG AbstractEntityPersister:2863 - test.ehcache.hibernateUse.Student.name is dirty
15:57:56,521 DEBUG DefaultFlushEntityEventListener:222 - Updating entity: [test.ehcache.hibernateUse.Student#3]
15:57:56,531 DEBUG AbstractFlushingEventListener:209 - Processing unreferenced collections
15:57:56,531 DEBUG AbstractFlushingEventListener:223 - Scheduling collection removes/(re)creates/updates
15:57:56,531 DEBUG AbstractFlushingEventListener:85 - Flushed: 1 insertions, 1 updates, 0 deletions to 1 objects
15:57:56,531 DEBUG AbstractFlushingEventListener:91 - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections
15:57:56,541 DEBUG Printer:83 - listing entities:
15:57:56,541 DEBUG Printer:90 - test.ehcache.hibernateUse.Student{name=xiaowei, id=3}
15:57:56,541 DEBUG AbstractFlushingEventListener:289 - executing flush
15:57:56,541 DEBUG ConnectionManager:463 - registering flush begin
15:57:56,551 DEBUG AbstractEntityPersister:2034 - Inserting entity: [test.ehcache.hibernateUse.Student#3]
15:57:56,551 DEBUG AbstractBatcher:311 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
15:57:56,551 DEBUG SQL:346 - insert into student (name, id) values (?, ?)
Hibernate: insert into student (name, id) values (?, ?)
15:57:56,561 DEBUG AbstractBatcher:424 - preparing statement
15:57:56,571 DEBUG AbstractEntityPersister:1821 - Dehydrating entity: [test.ehcache.hibernateUse.Student#3]
15:57:56,571 DEBUG StringType:80 - binding 'xiao' to parameter: 1
15:57:56,571 DEBUG IntegerType:80 - binding '3' to parameter: 2
15:57:56,571 DEBUG AbstractBatcher:28 - Adding to batch
15:57:56,591 DEBUG AbstractBatcher:55 - Executing batch size: 1
15:57:56,591 DEBUG AbstractBatcher:319 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
15:57:56,591 DEBUG AbstractBatcher:470 - closing statement
15:57:56,601 DEBUG ReadWriteCache:113 - Invalidating: test.ehcache.hibernateUse.Student#3
15:57:56,601 DEBUG EhCache:77 - key: test.ehcache.hibernateUse.Student#3
15:57:56,601 DEBUG MemoryStore:138 - test.ehcache.hibernateUse.StudentCache: test.ehcache.hibernateUse.StudentMemoryStore miss for test.ehcache.hibernateUse.Student#3
15:57:56,601 DEBUG Cache:662 - test.ehcache.hibernateUse.Student cache - Miss
15:57:56,601 DEBUG EhCache:85 - Element for test.ehcache.hibernateUse.Student#3 is null
15:57:56,631 DEBUG AbstractEntityPersister:2149 - Updating entity: [test.ehcache.hibernateUse.Student#3]
15:57:56,631 DEBUG AbstractBatcher:311 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
15:57:56,631 DEBUG SQL:346 - update student set name=? where id=?
Hibernate: update student set name=? where id=?
15:57:56,631 DEBUG AbstractBatcher:424 - preparing statement
15:57:56,641 DEBUG AbstractEntityPersister:1821 - Dehydrating entity: [test.ehcache.hibernateUse.Student#3]
15:57:56,641 DEBUG StringType:80 - binding 'xiaowei' to parameter: 1
15:57:56,641 DEBUG IntegerType:80 - binding '3' to parameter: 2
15:57:56,651 DEBUG AbstractBatcher:28 - Adding to batch
15:57:56,651 DEBUG AbstractBatcher:55 - Executing batch size: 1
15:57:56,661 DEBUG AbstractBatcher:319 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
15:57:56,661 DEBUG AbstractBatcher:470 - closing statement
15:57:56,661 DEBUG ConnectionManager:472 - registering flush end
15:57:56,671 DEBUG AbstractFlushingEventListener:320 - post flush
15:57:56,671 DEBUG JDBCContext:185 - before transaction completion
15:57:56,671 DEBUG SessionImpl:388 - before transaction completion
15:57:56,921 DEBUG JDBCTransaction:116 - committed JDBC Connection
15:57:56,921 DEBUG JDBCContext:199 - after transaction completion
15:57:56,921 DEBUG ConnectionManager:398 - aggressively releasing JDBC connection
15:57:56,921 DEBUG ConnectionManager:435 - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
15:57:56,921 DEBUG DriverManagerConnectionProvider:129 - returning connection to pool, pool size: 1
15:57:56,991 DEBUG SessionImpl:417 - after transaction completion
15:57:56,991 DEBUG ReadWriteCache:285 - Inserting: test.ehcache.hibernateUse.Student#3
15:57:56,991 DEBUG EhCache:77 - key: test.ehcache.hibernateUse.Student#3
15:57:56,991 DEBUG MemoryStore:135 - test.ehcache.hibernateUse.StudentCache: test.ehcache.hibernateUse.StudentMemoryStore hit for test.ehcache.hibernateUse.Student#3
15:57:56,991 DEBUG ReadWriteCache:246 - Updating: test.ehcache.hibernateUse.Student#3
15:57:57,011 DEBUG EhCache:77 - key: test.ehcache.hibernateUse.Student#3
15:57:57,011 DEBUG MemoryStore:135 - test.ehcache.hibernateUse.StudentCache: test.ehcache.hibernateUse.StudentMemoryStore hit for test.ehcache.hibernateUse.Student#3
15:57:57,021 DEBUG ReadWriteCache:263 - Updated: test.ehcache.hibernateUse.Student#3
15:57:57,021 DEBUG SessionImpl:268 - closing session
15:57:57,021 DEBUG ConnectionManager:369 - connection already null in cleanup : no action
15:57:57,031  INFO TestHibernateUse:34 - xiaowei
15:57:57,041  INFO CacheManager:503 - VM shutting down with the CacheManager still active. Calling shutdown.
15:57:57,041 DEBUG MemoryStore:218 - test.ehcache.hibernateUse.Student is persistent. Spooling 1 elements to the disk store.
15:57:57,041 DEBUG MemoryStore:263 - test.ehcache.hibernateUse.StudentCache: spool to disk done for: test.ehcache.hibernateUse.Student#3
15:57:57,041 DEBUG DiskStore:525 - Deleting file test.ehcache.hibernateUse.Student.data

看看，这样的调试信息，算不算EHCache 应用成功啊，谢谢！