客户现场出现一个问题,我在Java代码中只调用了一次SQL,正常情况下执行一次,跟踪日志中打出一行sql语句就完了;现在问题是跟踪日志中重复不断的打出sql语句,不知道成功执行了几次。跟踪日志贴出来如下:
2014-03-07 02:01:27,096 INFO - [1093]NAV Write WQ SQL=INSERT INTO WQ_INFO (QueueUID,Source_type,local_entry_UID,Parent_HUID,Entry_Name,Entry_type,Operation_type,Operation_time) VALUES ( N'W14394667',2, N'0', N'0', N'0',5,99,'2014-03-07 02:01:27')
2014-03-07 02:01:27,096 INFO - [1093]Execute Result=1
2014-03-07 02:01:27,518 INFO - [1093]NAV Write WQ SQL=INSERT INTO WQ_INFO (QueueUID,Source_type,local_entry_UID,Parent_HUID,Entry_Name,Entry_type,Operation_type,Operation_time) VALUES ( N'W14394668',2, N'0', N'0', N'0',5,99,'2014-03-07 02:01:27')
2014-03-07 02:01:27,533 INFO - [1093]Execute Result=1
2014-03-07 02:01:27,861 INFO - [1093]NAV Write WQ SQL=INSERT INTO WQ_INFO (QueueUID,Source_type,local_entry_UID,Parent_HUID,Entry_Name,Entry_type,Operation_type,Operation_time) VALUES ( N'W14394669',2, N'0', N'0', N'0',5,99,'2014-03-07 02:01:27')
2014-03-07 02:01:27,861 INFO - [1093]Execute Result=1
2014-03-07 02:01:28,252 INFO - [1093]NAV Write WQ SQL=INSERT INTO WQ_INFO (QueueUID,Source_type,local_entry_UID,Parent_HUID,Entry_Name,Entry_type,Operation_type,Operation_time) VALUES ( N'W14394670',2, N'0', N'0', N'0',5,99,'2014-03-07 02:01:28')
2014-03-07 02:01:28,252 INFO - [1093]Execute Result=1
2014-03-07 02:01:28,565 INFO - [1093]NAV Write WQ SQL=INSERT INTO WQ_INFO (QueueUID,Source_type,local_entry_UID,Parent_HUID,Entry_Name,Entry_type,Operation_type,Operation_time) VALUES ( N'W14394671',2, N'0', N'0', N'0',5,99,'2014-03-07 02:01:28')
2014-03-07 02:01:28,565 INFO - [1093]Execute Result=1
2014-03-07 02:01:28,940 INFO - [1093]NAV Write WQ SQL=INSERT INTO WQ_INFO (QueueUID,Source_type,local_entry_UID,Parent_HUID,Entry_Name,Entry_type,Operation_type,Operation_time) VALUES ( N'W14394672',2, N'0', N'0', N'0',5,99,'2014-03-07 02:01:28')
2014-03-07 02:01:28,940 INFO - [1093]Execute Result=1
2014-03-07 02:01:29,221 INFO - [1093]NAV Write WQ SQL=INSERT INTO WQ_INFO (QueueUID,Source_type,local_entry_UID,Parent_HUID,Entry_Name,Entry_type,Operation_type,Operation_time) VALUES ( N'W14394673',2, N'0', N'0', N'0',5,99,'2014-03-07 02:01:29')
2014-03-07 02:01:29,221 INFO - [1093]Execute Result=1
2014-03-07 02:01:29,471 INFO - [1093]NAV Write WQ SQL=INSERT INTO WQ_INFO (QueueUID,Source_type,local_entry_UID,Parent_HUID,Entry_Name,Entry_type,Operation_type,Operation_time) VALUES ( N'W14394674',2, N'0', N'0', N'0',5,99,'2014-03-07 02:01:29')
2014-03-07 02:01:29,486 INFO - [1093]Execute Result=1
2014-03-07 02:01:32,580 INFO - [1093]NAV Write WQ SQL=INSERT INTO WQ_INFO (QueueUID,Source_type,local_entry_UID,Parent_HUID,Entry_Name,Entry_type,Operation_type,Operation_time) VALUES ( N'W14394675',2, N'0', N'0', N'0',5,99,'2014-03-07 02:01:32')
2014-03-07 02:01:32,580 INFO - [1093]Execute Result=1
2014-03-07 02:01:36,377 INFO - [1093]NAV Write WQ SQL=INSERT INTO WQ_INFO (QueueUID,Source_type,local_entry_UID,Parent_HUID,Entry_Name,Entry_type,Operation_type,Operation_time) VALUES ( N'W14394676',2, N'0', N'0', N'0',5,99,'2014-03-07 02:01:36')
2014-03-07 02:01:36,377 INFO - [1093]Execute Result=1
....
正常情况下执行的日志应该是:
2014-03-07 08:25:47,973 DEBUG - [3018]MetadataPresentingDAO.createMetaData(): add metadata finished
2014-03-07 08:25:48,020 INFO - [3018]NAV Write WQ SQL=INSERT INTO WQ_INFO (QueueUID,Source_type,local_entry_UID,Parent_HUID,Entry_Name,Entry_type,Operation_type,Operation_time) VALUES ( N'W14397490',2, N'0', N'0', N'0',5,99,'2014-03-07 08:25:48')
2014-03-07 08:25:48,020 INFO - [3018]Execute Result=1
2014-03-07 08:25:48,176 INFO - [3018]ProgramPresentingDAO.existProgram(): sql=SELECT count(*) FROM pm_program_presenting WHERE program_id = '6511403081900000'
2014-03-07 08:25:48,192 INFO - [3018]ProgramPresentingDAO.existProgram(): affectedRows=1
即这条语句执行前后都会有其他语句执行。
这种不正常的现象足足持续了两天,日志中也一直打印上述语句,不时还出现其他线程的日志,但是线程号都是一样的,后来就出现内存溢出,日志如下:
2014-03-07 04:42:26,611 DEBUG - [1093][LAM] LamConfigManager->getConfigValue From ConfigApp ( MasterPort ) return 8080
2014-03-07 04:57:25,480 ERROR - [1093]
java.lang.OutOfMemoryError: Java heap space
2014-03-07 04:58:02,700 DEBUG - [1093][LAM] LamConfigManager->getConfigValue From ConfigApp ( MasterPort ) return 8080
2014-03-07 06:26:13,805 ERROR - [1093]