2014-11-24 52 views
0

我試圖從關係數據庫導入數據到neo4j。過程是這樣的(簡單一點):春季數據neo4j - tx.close()持續時間太長

while (!sarBatchService.isFinished()) { 

     logger.info("New batch started"); 

     Date loadDeklFrom = sarBatchService.getStartDateForNewBatch(); 
     Date loadDeklTo = sarBatchService 
       .getEndDateForNewBatch(loadDeklFrom); // = loadDeklFrom + 2 hours 

     logger.info("Dates calculated"); 

     Date startTime = new Date(); 

     List<Dek> deks = dekLoadManager 
       .loadAllDeks(loadDeklFrom, loadDeklTo); // loading data from the relational database (POINT A) 

     Date endLoadTime = new Date(); 

     logger.info("Deks loaded"); 

     GraphDatabase gdb = template.getGraphDatabase(); 
     Transaction tx = gdb.beginTx(); 

     logger.info("Transaction started!"); 

     try { 

      for (Deks dek : deks) { 

       /* transform dek into nodes, and save 
       this nodes with Neo4jTemplate.save() */ 
      } 

      logger.info("Deks saved"); 

      Date endImportTime = new Date(); 

      int aff = sarBatchService.insertBatchData(loadDeklFrom, 
        loadDeklTo, startTime, endLoadTime, endImportTime, 
        deks.size()); // (POINT B) 
      if (aff != 1) { 
       String msg = "Something went wrong", 

       throw new RuntimeException(msg); 
      } 

      logger.info("Batch data saved into relational database"); 

      tx.success(); 

      logger.info("Transaction marked as success."); 
     } catch (NoSuchFieldException | SecurityException 
       | IllegalArgumentException | IllegalAccessException 
       | NoSuchMethodException | InstantiationException 
       | InvocationTargetException e1) { 

      logger.error("Something bad happend :("); 
      logger.error(e1.getStackTrace().toString()); 
     } finally { 
      logger.info("Closing transaction..."); 

      tx.close(); // (POINT C) 

      logger.info("Transaction closed!"); 
      logger.info("Need more work? " + !sarBatchService.isFinished()); 
     } 
    } 

因此,在關係數據庫中的數據具有時間戳時,它的存儲和我加載它在兩小時兩個小時的時間間隔指示(POINT A在代碼中)。之後,我遍歷加載的數據,將其轉換爲節點(spring-data-neo4j節點),存儲在neo4j中,並在關係數據庫中存儲有關當前批次的信息(POINT B)。我正在記錄幾乎每一步,以更輕鬆地進行調試。

程序成功完成158批次。問題從第159批開始。程序停在代碼(tx.close())中的POINT C處,並在那裏等待4小時(通常持續幾秒鐘)。之後,正常繼續。

我試着在10GB堆大小和4GB堆大小的Tomcat 7上運行它。結果是一樣的(第159批)。一次交易中節點的最大數量在10k到15k之間(平均7k),第159批次節點少於10k個。

有趣的部分是,如果數據是4小時4小時或12小時12小時加載的,一切都會進展順利。另外,如果我重新啓動Tomcat或僅執行第159批次,所有通過都沒有問題。

我使用spring-data-neo4j 3.0.2的spring 3.2.8。

這是Neo4j的的message.log:

... 
2014-11-24 15:21:38.080+0000 WARN [o.n.k.EmbeddedGraphDatabase]: GC Monitor: Application threads blocked for an additional 418ms [total block time: 150.973s] 
2014-11-24 15:21:45.722+0000 WARN [o.n.k.EmbeddedGraphDatabase]: GC Monitor: Application threads blocked for an additional 377ms [total block time: 151.35s] 
... 
2014-11-24 15:23:57.381+0000 WARN [o.n.k.EmbeddedGraphDatabase]: GC Monitor: Application threads blocked for an additional 392ms [total block time: 156.593s] 
2014-11-24 15:24:06.758+0000 INFO [o.n.k.i.t.x.XaLogicalLog]: Rotating  [/home/pravila/data/neo4j/nioneo_logical.log.1] @ version=22 to /home/pravila/data/neo4j/nioneo_logical.log.2 from position 26214444 
2014-11-24 15:24:06.763+0000 INFO [o.n.k.i.t.x.XaLogicalLog]: Rotate log first start entry @ pos=24149878 out of [339=Start[339,xid=GlobalId[NEOKERNL|5889317606667601380|364|-1], BranchId[ 52 49 52 49 52 49 ],master=-1,me=-1,time=2014-11-24 15:23:13.021+0000/1416842593021,lastCommittedTxWhenTransactionStarted=267]] 
2014-11-24 15:24:07.401+0000 INFO [o.n.k.i.t.x.XaLogicalLog]: Rotate: old log scanned, newLog @ pos=2064582 
2014-11-24 15:24:07.402+0000 INFO [o.n.k.i.t.x.XaLogicalLog]: Log rotated, newLog @ pos=2064582, version 23 and last tx 267 
2014-11-24 15:24:07.684+0000 INFO [o.n.k.i.t.x.XaLogicalLog]: Rotating [/home/pravila/data/neo4j/index/lucene.log.1] @ version=6 to /home/pravila/data/neo4j/index/lucene.log.2 from position 26214408 
2014-11-24 15:24:07.772+0000 INFO [o.n.k.i.t.x.XaLogicalLog]: Rotate log first start entry @ pos=25902494 out of [134=Start[134,xid=GlobalId[NEOKERNL|5889317606667601380|364|-1], BranchId[ 49 54 50 51 55 52 ],master=-1,me=-1,time=2014-11-24  15:23:13.023+0000/1416842593023,lastCommittedTxWhenTransactionStarted=133]] 
2014-11-24 15:24:07.871+0000 INFO [o.n.k.i.t.x.XaLogicalLog]: Rotate: old log scanned, newLog @ pos=311930 
2014-11-24 15:24:07.878+0000 INFO [o.n.k.i.t.x.XaLogicalLog]: Log rotated, newLog @ pos=311930, version 7 and last tx 133 
2014-11-24 15:24:10.919+0000 WARN [o.n.k.EmbeddedGraphDatabase]: GC Monitor: Application threads blocked for an additional 214ms [total block time: 156.807s] 
2014-11-24 15:24:17.486+0000 WARN [o.n.k.EmbeddedGraphDatabase]: GC Monitor: Application threads blocked for an additional 405ms [total block time: 157.212s] 
... 
2014-11-24 15:25:28.692+0000 WARN [o.n.k.EmbeddedGraphDatabase]: GC Monitor: Application threads blocked for an additional 195ms [total block time: 159.316s] 
2014-11-24 15:25:33.238+0000 INFO [o.n.k.i.t.x.XaLogicalLog]: Rotating [/home/pravila/data/neo4j/nioneo_logical.log.2] @ version=23 to /home/pravila/data/neo4j/nioneo_logical.log.1 from position 26214459 
2014-11-24 15:25:33.242+0000 INFO [o.n.k.i.t.x.XaLogicalLog]: Rotate log first start entry @ pos=24835943 out of [349=Start[349,xid=GlobalId[NEOKERNL|-6436474643536791121|374|-1], BranchId[ 52 49 52 49 52 49 ],master=-1,me=-1,time=2014-11-24 15:25:27.038+0000/1416842727038,lastCommittedTxWhenTransactionStarted=277]] 
2014-11-24 15:25:33.761+0000 INFO [o.n.k.i.t.x.XaLogicalLog]: Rotate: old log scanned, newLog @ pos=1378532 
2014-11-24 15:25:33.763+0000 INFO [o.n.k.i.t.x.XaLogicalLog]: Log rotated, newLog @ pos=1378532, version 24 and last tx 277 
2014-11-24 15:25:37.031+0000 WARN [o.n.k.EmbeddedGraphDatabase]: GC Monitor: Application threads blocked for an additional 148ms [total block time: 159.464s] 
2014-11-24 15:25:45.891+0000 WARN [o.n.k.EmbeddedGraphDatabase]: GC Monitor: Application threads blocked for an additional 153ms [total block time: 159.617s] 
....  
2014-11-24 15:26:48.447+0000 WARN [o.n.k.EmbeddedGraphDatabase]: GC Monitor: Application threads blocked for an additional 221ms [total block time: 161.641s] 

我不知道是怎麼回事......

請幫助。

回答

0

經過數小時的搜索和測試後,我試圖以4乘4小時的時間間隔重新運行整批。它也在第145批(交易)後停止。不同的是它拋出一個錯誤(打開的文件太多)。我將打開文件的ulimit設置爲無限制,現在它可以工作。唯一的謎就是爲什麼程序沒有第一次拋出錯誤。

0

它看起來很像你在那裏有一個泄漏的外部交易。

這樣你顯示的內部事務實際上結束了,而外部事務繼續積累狀態。作爲新不暫停外交易而純粹巢他們就不會有真正的承諾,直到你遇到外tx.success(); tx.close();

您應該看到,如果你把線程轉儲時,看它是否塊它實際上是停留在承諾。

+0

嗨邁克爾,tnx爲您的答覆。我寫的while循環基本上是函數的全部(預定函數)。除了循環內的其他事務外,我沒有明確地打開任何其他事務。是否仍有可能存在外部neo4j事務?另外,我從來沒有讀過線程轉儲。我執行kill -3 [tomcat pid],現在我有一個大文件,我現在不知道如何閱讀:)我應該搜索什麼? – Markotron 2014-11-25 10:19:22

+0

我試圖運行4小時4小時的批次,並且它也停止了第145次交易。看起來程序很難連續打開和關閉很多事務。 – Markotron 2014-11-26 13:42:01