Hi. I've got a repeatable problem with Jena 3.1 when performing a bulk load.
The bulk load converts a file into ~200k quads and adds them to a TDB instance within a normal begin write, add quads and commit. Initially this completes in 30-40 seconds, However if I repeat the process (with the same file) on the 5th iteration I get a OOME exception. As I'm importing the same file into different graphs I would expect the DAT file to stay the same size after the first process and just the index files to grow. There are no other process running against the TDB whilst this process is run. Using jmap the [B grows with each process until finally I get the exception. If I increase the Xmx the OOME occurs later. Any ideas? I've included details below, including jmap output which shows the heap being used and the JVM output which shows the GC (Allocation Failure) entries transiting to Full GC (Economics) entries... Regards Dick. JVM args -Xms2g -Xmx4g -XX:+PrintGCDetails -javaagent:/home/dick/eclipse-jee-neon/opt/classmexer-0_03/classmexer.jar dick@Dick-M3800:~$ uname -a Linux Dick-M3800 4.4.0-31-generic #50-Ubuntu SMP Wed Jul 13 00:07:12 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux dick@Dick-M3800:~$ java -version openjdk version "1.8.0_91" OpenJDK Runtime Environment (build 1.8.0_91-8u91-b14-0ubuntu4~16.04.1-b14) OpenJDK 64-Bit Server VM (build 25.91-b14, mixed mode) dick@Dick-M3800:~$ Output from jmap dick@Dick-M3800:~$ jmap -histo 15031 | head -25 num #instances #bytes class name ---------------------------------------------- 1: 132187 636210296 [B 2: 500242 31189608 [C 3: 533380 25602240 org.apache.jena.ext.com.google.common.cache.LocalCache$StrongAccessEntry 4: 468220 18728800 org.kabeja.math.Point3D 5: 349351 16768848 org.kabeja.entities.Vertex 6: 1654 16374552 [I 7: 445589 16219672 [Ljava.lang.Object; dick@Dick-M3800:~$ jmap -histo 15031 | head -25 num #instances #bytes class name ---------------------------------------------- 1: 1148534 1420727464 [B 2: 5961841 344220520 [C 3: 1335412 85466368 java.nio.DirectByteBuffer 4: 3453219 82877256 java.lang.String 5: 573585 65399360 [I 6: 1261244 60539712 org.apache.jena.ext.com.google.common.cache.LocalCache$StrongAccessEntry 7: 945955 36365560 [Ljava.lang.Object; dick@Dick-M3800:~$ jmap -histo 15031 | head -25 num #instances #bytes class name ---------------------------------------------- 1: 1377821 2328657400 [B 2: 7566951 434495472 [C 3: 1717606 109926784 java.nio.DirectByteBuffer 4: 4339997 104159928 java.lang.String 5: 749581 75578568 [I 6: 1485127 71286096 org.apache.jena.ext.com.google.common.cache.LocalCache$StrongAccessEntry 7: 1089303 42230696 [Ljava.lang.Object; dick@Dick-M3800:~$ jmap -histo 15031 | head -25 num #instances #bytes class name ---------------------------------------------- 1: 333123 2285460248 [B 2: 604102 38062832 [C 3: 660301 31694448 org.apache.jena.ext.com.google.common.cache.LocalCache$StrongAccessEntry 4: 468220 18728800 org.kabeja.math.Point3D 5: 349351 16768848 org.kabeja.entities.Vertex 6: 445689 16486104 [Ljava.lang.Object; 7: 590752 14178048 java.lang.String 8: 278273 13357104 java.nio.HeapByteBuffer 9: 530557 12733368 org.apache.jena.tdb.store.NodeId 10: 420 11221544 [Ljava.util.HashMap$Node; 11: 334514 10704448 java.util.HashMap$Node 12: 660301 10564816 org.apache.jena.ext.com.google.common.cache.LocalCache$StrongValueReference 13: 420443 10090632 org.kabeja.tools.LazyContainer 14: 278249 8903968 org.apache.jena.tdb.base.block.Block 15: 201719 8068760 org.apache.jena.graph.impl.LiteralLabelImpl 16: 227185 5452440 java.lang.Long 17: 257247 4115952 org.apache.jena.graph.BlankNodeId 18: 257247 4115952 org.apache.jena.graph.Node_Blank 19: 1694 3770384 [I 20: 201719 3227504 org.apache.jena.graph.Node_Literal 21: 17199 2476656 org.kabeja.entities.Attrib 22: 91570 2197680 java.lang.Double dick@Dick-M3800:~$ jmap -histo 15031 | head -10 num #instances #bytes class name ---------------------------------------------- 1: 333123 2285460248 [B 2: 604102 38062832 [C 3: 660301 31694448 org.apache.jena.ext.com.google.common.cache.LocalCache$StrongAccessEntry 4: 468220 18728800 org.kabeja.math.Point3D 5: 349351 16768848 org.kabeja.entities.Vertex 6: 445689 16486104 [Ljava.lang.Object; 7: 590752 14178048 java.lang.String dick@Dick-M3800:~$ jmap -histo 15031 | head -13 num #instances #bytes class name ---------------------------------------------- 1: 333123 2285460248 [B 2: 604102 38062832 [C 3: 660301 31694448 org.apache.jena.ext.com.google.common.cache.LocalCache$StrongAccessEntry 4: 468220 18728800 org.kabeja.math.Point3D 5: 349351 16768848 org.kabeja.entities.Vertex 6: 445689 16486104 [Ljava.lang.Object; 7: 590752 14178048 java.lang.String 8: 278273 13357104 java.nio.HeapByteBuffer 9: 530557 12733368 org.apache.jena.tdb.store.NodeId 10: 420 11221544 [Ljava.util.HashMap$Node; dick@Dick-M3800:~$ jmap -histo 15031 | head -13 num #instances #bytes class name ---------------------------------------------- 1: 934984 3083070024 [B 2: 798242 51297104 [C 3: 842007 40416336 java.nio.HeapByteBuffer 4: 697063 33459024 org.apache.jena.ext.com.google.common.cache.LocalCache$StrongAccessEntry 5: 581662 23266480 org.kabeja.math.Point3D 6: 630910 20189120 java.util.HashMap$Node 7: 349351 16768848 org.kabeja.entities.Vertex 8: 445723 16618536 [Ljava.lang.Object; 9: 664750 15954000 org.apache.jena.tdb.store.NodeId 10: 639327 15343848 java.lang.String dick@Dick-M3800:~$ jmap -histo 15031 | head -13 num #instances #bytes class name ---------------------------------------------- 1: 1067937 3321067472 [B 2: 1935834 114366720 [C 3: 734818 35271264 org.apache.jena.ext.com.google.common.cache.LocalCache$StrongAccessEntry 4: 1262875 30309000 java.lang.String 5: 759345 24299040 java.util.HashMap$Node 6: 570771 21620680 [Ljava.lang.Object; 7: 333915 21370560 java.nio.DirectByteBuffer 8: 443744 21299712 java.nio.HeapByteBuffer 9: 468220 18728800 org.kabeja.math.Point3D 10: 548013 17536416 org.apache.jena.tdb.base.block.Block dick@Dick-M3800:~$ jmap -histo 15031 | head -13 num #instances #bytes class name ---------------------------------------------- 1: 581039 3615795256 [B 2: 624485 39191288 [C 3: 700593 33628464 org.apache.jena.ext.com.google.common.cache.LocalCache$StrongAccessEntry 4: 440069 21123312 java.nio.HeapByteBuffer 5: 607056 19425792 java.util.HashMap$Node 6: 445421 17816840 org.kabeja.math.Point3D 7: 422565 16272432 [Ljava.lang.Object; 8: 326910 15691680 org.kabeja.entities.Vertex 9: 433 15577272 [Ljava.util.HashMap$Node; 10: 611550 14677200 java.lang.String dick@Dick-M3800:~$ Output from JVM. dataset node "TDB" bulkload source type "image/vnd.dxf" url "file:///home/dick/eclipse-jee-neon/git/iungo-ssl/iungo-ssl/test/resources/0005_XXXX-SSL-XXX-XX-DR-U-0200.dxf" METHOD 2016-07-26T08:26:36.824Z org.iungo.dataset.tdb.node.TDBDatasetNode#TDB bulkload#2 org.iungo.result.Result bulkload(org.iungo.context.Context) DEBUG 2016-07-26T08:26:36.833Z RootLogger Thread-5 process ([ID [bdb348e4-0f33-481c-8af9-dee18583d917] Result [null]]) true Added bulkload org.iungo.queue.EntryDEBUG 2016-07-26T08:26:36.833Z RootLogger Thread-5 org.iungo.lang.ClassUtils.create(org.iungo.dataset.bulkload.DXFDatasetBulkload, [Ljava.lang.Class;@17790d45, [Ljava.lang.Object;@19bef1da) INFO 2016-07-26T08:26:36.838Z RootLogger org.iungo.logger.AbstractLogger#4 Started [Logger [org.iungo.logger.SystemLogger] Name [org.iungo.dataset.bulkload.DXFDatasetBulkload#1] Level [ALL] Counts [3/0/0]] INFO 2016-07-26T08:26:36.838Z org.iungo.dataset.bulkload.DXFDatasetBulkload#1 Set level to [ALL] METHOD 2016-07-26T08:26:36.838Z org.iungo.dataset.bulkload.DXFDatasetBulkload#1 bulkload#3 org.iungo.result.Result bulkload(org.iungo.context.Context) TRY_BLOCK 2016-07-26T08:26:36.838Z org.iungo.dataset.bulkload.DXFDatasetBulkload#1 bulkload#3 Try [null] TRY_BLOCK 2016-07-26T08:26:36.838Z org.iungo.dataset.bulkload.DXFDatasetBulkload#1 bulkload#3 Try [URL input stream] RETURN 2016-07-26T08:26:36.833Z org.iungo.dataset.tdb.node.TDBDatasetNode#TDB bulkload#2 Return Timer [Started [2016:07:26 09:26:36] Stopped [2016:07:26 09:26:36] Elapsed [9ms]] Value [org.iungo.result.Result] VARIABLE 2016-07-26T08:26:36.846Z org.iungo.dataset.tdb.node.TDBDatasetNode#TDB bulkload#2 Return Value [true [Added bulkload] [org.iungo.queue.Entry]] CALL_TRY 2016-07-26T08:26:36.878Z org.iungo.dataset.bulkload.DXFDatasetBulkload#1 bulkload#3 [2016-07-26T08:26:36.878Z] [DXF Parser parse] [GC (Allocation Failure) [PSYoungGen: 524800K->31301K(611840K)] 524800K->31381K(2010112K), 0.0424604 secs] [Times: user=0.20 sys=0.06, real=0.04 secs] WARN 2016-07-26T08:26:37.652Z RootLogger Finalizer Return value not called [Logger [Logger [org.iungo.logger.SystemLogger] Name [org.iungo.dataset.tdb.node.TDBDatasetNode#TDB] Level [INFO] Counts [3/3/0]] Name [bulkload#2] Timer [Started [2016:07:26 09:26:36] Stopped [2016:07:26 09:26:36] Elapsed [9ms]]] CALL_FINALLY 2016-07-26T08:26:37.814Z org.iungo.dataset.bulkload.DXFDatasetBulkload#1 bulkload#3 Call [2016-07-26T08:26:37.814Z] [DXF Parser parse] CALL_TRY 2016-07-26T08:26:37.815Z org.iungo.dataset.bulkload.DXFDatasetBulkload#1 bulkload#3 [2016-07-26T08:26:37.815Z] [sizeOf(Object)#Object] CALL_FINALLY 2016-07-26T08:26:37.816Z org.iungo.dataset.bulkload.DXFDatasetBulkload#1 bulkload#3 Call [2016-07-26T08:26:37.816Z] [sizeOf(Object)#Object] CALL_TRY 2016-07-26T08:26:37.816Z org.iungo.dataset.bulkload.DXFDatasetBulkload#1 bulkload#3 [2016-07-26T08:26:37.816Z] [sizeOf(Object)#References] CALL_FINALLY 2016-07-26T08:26:38.333Z org.iungo.dataset.bulkload.DXFDatasetBulkload#1 bulkload#3 Call [2016-07-26T08:26:38.333Z] [sizeOf(Object)#References] SIZE_OF 2016-07-26T08:26:38.334Z org.iungo.dataset.bulkload.DXFDatasetBulkload#1 bulkload#3 Variable [draftDocument] = [72/27301560] VARIABLE 2016-07-26T08:26:38.334Z org.iungo.dataset.bulkload.DXFDatasetBulkload#1 bulkload#3 Variable [g] = [urn:iungo:dxf/graph/af64364c-7424-4eba-ad7a-798c21821650] CALL_TRY 2016-07-26T08:26:38.335Z org.iungo.dataset.bulkload.DXFDatasetBulkload#1 bulkload#3 [2016-07-26T08:26:38.335Z] [Dataset write] CALL_FINALLY 2016-07-26T08:26:38.347Z org.iungo.dataset.bulkload.DXFDatasetBulkload#1 bulkload#3 Call [2016-07-26T08:26:38.346Z] [Dataset write] TRY_BLOCK 2016-07-26T08:26:38.347Z org.iungo.dataset.bulkload.DXFDatasetBulkload#1 bulkload#3 Try [Visitor] DEBUG 2016-07-26T08:26:38.347Z RootLogger Thread-5 DXF [Layers [0] Blocks [0] Entities [0] LWPolyline [0] LW2DVertex [0] Bounds [0] Quads [0]] Process [Interval [10000] Timer [Started [2016:07:26 09:26:38] Running Elapsed [0ms]]] CALL_TRY 2016-07-26T08:26:38.352Z org.iungo.dataset.bulkload.DXFDatasetBulkload#1 bulkload#3 [2016-07-26T08:26:38.352Z] [Visitor] [GC (Allocation Failure) [PSYoungGen: 556101K->33176K(611840K)] 556181K->33272K(2010112K), 0.0378728 secs] [Times: user=0.14 sys=0.08, real=0.04 secs] [GC (Allocation Failure) [PSYoungGen: 557976K->87034K(611840K)] 558072K->107618K(2010112K), 0.1034050 secs] [Times: user=0.61 sys=0.09, real=0.11 secs] [GC (Allocation Failure) [PSYoungGen: 611834K->87022K(1136640K)] 632418K->149718K(2534912K), 0.1022982 secs] [Times: user=0.30 sys=0.37, real=0.10 secs] [GC (Allocation Failure) [PSYoungGen: 1136622K->87008K(1136640K)] 1199318K->217256K(2534912K), 0.1187315 secs] [Times: user=0.33 sys=0.45, real=0.12 secs] [GC (Allocation Failure) [PSYoungGen: 1136608K->172800K(1145856K)] 1266856K->303057K(2544128K), 0.1087404 secs] [Times: user=0.35 sys=0.39, real=0.10 secs] [GC (Allocation Failure) [PSYoungGen: 1126144K->222176K(1175552K)] 1256401K->376515K(2573824K), 0.0622131 secs] [Times: user=0.30 sys=0.09, real=0.06 secs] [GC (Allocation Failure) [PSYoungGen: 1175520K->222176K(966656K)] 1329859K->433901K(2364928K), 0.0803317 secs] [Times: user=0.39 sys=0.09, real=0.08 secs] DEBUG 2016-07-26T08:26:48.351Z RootLogger Thread-7 DXF [Layers [220] Blocks [264] Entities [48439] LWPolyline [1638] LW2DVertex [11886] Bounds [49608] Quads [810533]] Process [Interval [10000] Timer [Started [2016:07:26 09:26:38] Running Elapsed [10005ms]]] [GC (Allocation Failure) [PSYoungGen: 966624K->186400K(1071104K)] 1178349K->472365K(2469376K), 0.0867127 secs] [Times: user=0.38 sys=0.16, real=0.09 secs] [GC (Allocation Failure) [PSYoungGen: 930848K->120192K(1042944K)] 1216813K->501872K(2441216K), 0.0767022 secs] [Times: user=0.29 sys=0.18, real=0.07 secs] [GC (Allocation Failure) [PSYoungGen: 867200K->59072K(1058304K)] 1248880K->533021K(2456576K), 0.0869604 secs] [Times: user=0.28 sys=0.28, real=0.08 secs] CALL_FINALLY 2016-07-26T08:26:51.670Z org.iungo.dataset.bulkload.DXFDatasetBulkload#1 bulkload#3 Call [2016-07-26T08:26:51.670Z] [Visitor] CALL_TRY 2016-07-26T08:26:51.670Z org.iungo.dataset.bulkload.DXFDatasetBulkload#1 bulkload#3 [2016-07-26T08:26:51.670Z] [Visitor] [GC (Allocation Failure) [PSYoungGen: 806080K->44608K(1080320K)] 1280029K->562512K(2478592K), 0.0509676 secs] [Times: user=0.18 sys=0.13, real=0.05 secs] [GC (Allocation Failure) [PSYoungGen: 821824K->48352K(1084416K)] 1339728K->598834K(2482688K), 0.0407001 secs] [Times: user=0.15 sys=0.08, real=0.04 secs] [GC (Allocation Failure) [PSYoungGen: 825568K->52384K(1077760K)] 1376050K->638066K(2476032K), 0.0370391 secs] [Times: user=0.16 sys=0.01, real=0.04 secs] [GC (Allocation Failure) [PSYoungGen: 840352K->55584K(1083904K)] 1426034K->679568K(2482176K), 0.0393499 secs] [Times: user=0.17 sys=0.10, real=0.03 secs] DEBUG 2016-07-26T08:26:58.351Z RootLogger Thread-7 DXF [Layers [440] Blocks [703] Entities [117777] LWPolyline [3637] LW2DVertex [25661] Bounds [121118] Quads [1919732]] Process [Interval [10000] Timer [Started [2016:07:26 09:26:38] Running Elapsed [20004ms]]] [GC (Allocation Failure) [PSYoungGen: 843552K->49568K(1088000K)] 1467536K->714395K(2486272K), 0.0399583 secs] [Times: user=0.15 sys=0.11, real=0.04 secs] [GC (Allocation Failure) [PSYoungGen: 864160K->58560K(1093632K)] 1528987K->759621K(2491904K), 0.0383629 secs] [Times: user=0.19 sys=0.07, real=0.04 secs] CALL_FINALLY 2016-07-26T08:27:00.849Z org.iungo.dataset.bulkload.DXFDatasetBulkload#1 bulkload#3 Call [2016-07-26T08:27:00.849Z] [Visitor] CALL_TRY 2016-07-26T08:27:00.850Z org.iungo.dataset.bulkload.DXFDatasetBulkload#1 bulkload#3 [2016-07-26T08:27:00.850Z] [Dataset commit] [GC (Allocation Failure) [PSYoungGen: 873152K->39066K(1109504K)] 1574213K->784272K(2507776K), 0.0351013 secs] [Times: user=0.17 sys=0.05, real=0.04 secs] [GC (Allocation Failure) [PSYoungGen: 889498K->25856K(1111552K)] 1634704K->802171K(2509824K), 0.0375312 secs] [Times: user=0.22 sys=0.07, real=0.04 secs] [GC (Allocation Failure) [PSYoungGen: 876288K->23232K(1127424K)] 1652603K->820595K(2525696K), 0.0366533 secs] [Times: user=0.24 sys=0.02, real=0.04 secs] [GC (Allocation Failure) [PSYoungGen: 904896K->26464K(1129984K)] 1702259K->842555K(2528256K), 0.0367213 secs] [Times: user=0.25 sys=0.00, real=0.04 secs] [GC (Allocation Failure) [PSYoungGen: 908128K->24992K(1138688K)] 1724219K->862659K(2536960K), 0.0391041 secs] [Times: user=0.26 sys=0.00, real=0.04 secs] DEBUG 2016-07-26T08:27:08.351Z RootLogger Thread-7 DXF [Layers [440] Blocks [878] Entities [137566] LWPolyline [3998] LW2DVertex [27550] Bounds [141908] Quads [2203968]] Process [Interval [10000] Timer [Started [2016:07:26 09:26:38] Running Elapsed [30004ms]]] CALL_FINALLY 2016-07-26T08:27:09.393Z org.iungo.dataset.bulkload.DXFDatasetBulkload#1 bulkload#3 Call [2016-07-26T08:27:09.393Z] [Dataset commit] DEBUG 2016-07-26T08:27:09.394Z RootLogger Thread-5 DXF [Layers [440] Blocks [878] Entities [137566] LWPolyline [3998] LW2DVertex [27550] Bounds [141908] Quads [2203968]] Process [Interval [10000] Timer [Started [2016:07:26 09:26:38] Stopped [2016:07:26 09:27:09] Elapsed [31047ms]]] CALL_TRY 2016-07-26T08:27:09.395Z org.iungo.dataset.bulkload.DXFDatasetBulkload#1 bulkload#3 [2016-07-26T08:27:09.395Z] [Dataset end] DEBUG 2016-07-26T08:27:09.395Z RootLogger Thread-5 take() CALL_FINALLY 2016-07-26T08:27:09.395Z org.iungo.dataset.bulkload.DXFDatasetBulkload#1 bulkload#3 Call [2016-07-26T08:27:09.395Z] [Dataset end] FINALLY_BLOCK 2016-07-26T08:27:09.395Z org.iungo.dataset.bulkload.DXFDatasetBulkload#1 bulkload#3 Finally RETURN 2016-07-26T08:27:09.395Z org.iungo.dataset.bulkload.DXFDatasetBulkload#1 bulkload#3 Return Timer [Started [2016:07:26 09:26:36] Stopped [2016:07:26 09:27:09] Elapsed [32558ms]] Value [org.iungo.result.Result] VARIABLE 2016-07-26T08:27:09.396Z org.iungo.dataset.bulkload.DXFDatasetBulkload#1 bulkload#3 Return Value [true [DXF [Layers [440] Blocks [878] Entities [137566] LWPolyline [3998] LW2DVertex [27550] Bounds [141908] Quads [2203968]] Timer [Interval [10000] Timer [Started [2016:07:26 09:26:38] Stopped [2016:07:26 09:27:09] Elapsed [31047ms]]]] [java.lang.String]] iungo runtime true Processors [8] Memory MB [Total [2477(68%)] Free [1177(48%)] Max [3641]] (No value returned)iungo gc [GC (System.gc()) [PSYoungGen: 493704K->20032K(929792K)] 1331371K->879995K(2328064K), 0.0567158 secs] [Times: user=0.30 sys=0.06, real=0.05 secs] [Full GC (System.gc()) [PSYoungGen: 20032K->0K(929792K)] [ParOldGen: 859963K->814267K(1398272K)] 879995K->814267K(2328064K), [Metaspace: 18575K->18575K(1067008K)], 0.7482168 secs] [Times: user=4.75 sys=0.07, real=0.75 secs] true Before [Processors [8] Memory MB [Total [2477(68%)] Free [1177(48%)] Max [3641]]] After [Processors [8] Memory MB [Total [2273(62%)] Free [1471(65%)] Max [3641]]] (No value returned)WARN 2016-07-26T08:28:25.234Z RootLogger Finalizer Return value not called [Logger [Logger [org.iungo.logger.SystemLogger] Name [org.iungo.dataset.bulkload.DXFDatasetBulkload#1] Level [ALL] Counts [26/26/0]] Name [bulkload#3] Timer [Started [2016:07:26 09:26:36] Stopped [2016:07:26 09:27:09] Elapsed [32558ms]]] dataset node "TDB" bulkload source type "image/vnd.dxf" url "file:///home/dick/eclipse-jee-neon/git/iungo-ssl/iungo-ssl/test/resources/0005_XXXX-SSL-XXX-XX-DR-U-0200.dxf" METHOD 2016-07-26T08:29:57.849Z org.iungo.dataset.tdb.node.TDBDatasetNode#TDB bulkload#4 org.iungo.result.Result bulkload(org.iungo.context.Context) DEBUG 2016-07-26T08:29:57.849Z RootLogger Thread-5 process ([ID [a48c964d-d365-42f7-9435-e61b21869de2] Result [null]]) true Added bulkload org.iungo.queue.EntryDEBUG 2016-07-26T08:29:57.849Z RootLogger Thread-5 org.iungo.lang.ClassUtils.create(org.iungo.dataset.bulkload.DXFDatasetBulkload, [Ljava.lang.Class;@122fe874, [Ljava.lang.Object;@299ed608) RETURN 2016-07-26T08:29:57.849Z org.iungo.dataset.tdb.node.TDBDatasetNode#TDB bulkload#4 Return Timer [Started [2016:07:26 09:29:57] Stopped [2016:07:26 09:29:57] Elapsed [1ms]] Value [org.iungo.result.Result] VARIABLE 2016-07-26T08:29:57.849Z org.iungo.dataset.tdb.node.TDBDatasetNode#TDB bulkload#4 Return Value [true [Added bulkload] [org.iungo.queue.Entry]] INFO 2016-07-26T08:29:57.850Z RootLogger org.iungo.logger.AbstractLogger#5 Started [Logger [org.iungo.logger.SystemLogger] Name [org.iungo.dataset.bulkload.DXFDatasetBulkload#2] Level [ALL] Counts [1/0/0]] INFO 2016-07-26T08:29:57.850Z org.iungo.dataset.bulkload.DXFDatasetBulkload#2 Set level to [ALL] METHOD 2016-07-26T08:29:57.850Z org.iungo.dataset.bulkload.DXFDatasetBulkload#2 bulkload#5 org.iungo.result.Result bulkload(org.iungo.context.Context) TRY_BLOCK 2016-07-26T08:29:57.850Z org.iungo.dataset.bulkload.DXFDatasetBulkload#2 bulkload#5 Try [null] TRY_BLOCK 2016-07-26T08:29:57.850Z org.iungo.dataset.bulkload.DXFDatasetBulkload#2 bulkload#5 Try [URL input stream] CALL_TRY 2016-07-26T08:29:57.850Z org.iungo.dataset.bulkload.DXFDatasetBulkload#2 bulkload#5 [2016-07-26T08:29:57.850Z] [DXF Parser parse] CALL_FINALLY 2016-07-26T08:29:58.434Z org.iungo.dataset.bulkload.DXFDatasetBulkload#2 bulkload#5 Call [2016-07-26T08:29:58.433Z] [DXF Parser parse] CALL_TRY 2016-07-26T08:29:58.434Z org.iungo.dataset.bulkload.DXFDatasetBulkload#2 bulkload#5 [2016-07-26T08:29:58.433Z] [sizeOf(Object)#Object] CALL_FINALLY 2016-07-26T08:29:58.434Z org.iungo.dataset.bulkload.DXFDatasetBulkload#2 bulkload#5 Call [2016-07-26T08:29:58.433Z] [sizeOf(Object)#Object] CALL_TRY 2016-07-26T08:29:58.434Z org.iungo.dataset.bulkload.DXFDatasetBulkload#2 bulkload#5 [2016-07-26T08:29:58.433Z] [sizeOf(Object)#References] CALL_FINALLY 2016-07-26T08:29:58.868Z org.iungo.dataset.bulkload.DXFDatasetBulkload#2 bulkload#5 Call [2016-07-26T08:29:58.868Z] [sizeOf(Object)#References] SIZE_OF 2016-07-26T08:29:58.868Z org.iungo.dataset.bulkload.DXFDatasetBulkload#2 bulkload#5 Variable [draftDocument] = [72/27336336] VARIABLE 2016-07-26T08:29:58.868Z org.iungo.dataset.bulkload.DXFDatasetBulkload#2 bulkload#5 Variable [g] = [urn:iungo:dxf/graph/f57eadb0-680f-4bd9-9e53-9e0c89b3a392] CALL_TRY 2016-07-26T08:29:58.868Z org.iungo.dataset.bulkload.DXFDatasetBulkload#2 bulkload#5 [2016-07-26T08:29:58.868Z] [Dataset write] CALL_FINALLY 2016-07-26T08:29:58.870Z org.iungo.dataset.bulkload.DXFDatasetBulkload#2 bulkload#5 Call [2016-07-26T08:29:58.870Z] [Dataset write] TRY_BLOCK 2016-07-26T08:29:58.870Z org.iungo.dataset.bulkload.DXFDatasetBulkload#2 bulkload#5 Try [Visitor] DEBUG 2016-07-26T08:29:58.870Z RootLogger Thread-5 DXF [Layers [0] Blocks [0] Entities [0] LWPolyline [0] LW2DVertex [0] Bounds [0] Quads [0]] Process [Interval [10000] Timer [Started [2016:07:26 09:29:58] Running Elapsed [0ms]]] CALL_TRY 2016-07-26T08:29:58.870Z org.iungo.dataset.bulkload.DXFDatasetBulkload#2 bulkload#5 [2016-07-26T08:29:58.870Z] [Visitor] [GC (Allocation Failure) [PSYoungGen: 909312K->30273K(1143296K)] 1723579K->844540K(2541568K), 0.0180773 secs] [Times: user=0.10 sys=0.00, real=0.01 secs] WARN 2016-07-26T08:29:58.966Z RootLogger Finalizer Return value not called [Logger [Logger [org.iungo.logger.SystemLogger] Name [org.iungo.dataset.tdb.node.TDBDatasetNode#TDB] Level [INFO] Counts [6/6/0]] Name [bulkload#4] Timer [Started [2016:07:26 09:29:57] Stopped [2016:07:26 09:29:57] Elapsed [1ms]]] [GC (Allocation Failure) [PSYoungGen: 949825K->114208K(1133056K)] 1764092K->957885K(2531328K), 0.0413847 secs] [Times: user=0.27 sys=0.00, real=0.04 secs] [GC (Allocation Failure) [PSYoungGen: 1033760K->75344K(1166336K)] 1877437K->1015335K(2564608K), 0.0730055 secs] [Times: user=0.31 sys=0.17, real=0.07 secs] [GC (Allocation Failure) [PSYoungGen: 1041488K->77392K(1172480K)] 1981479K->1073770K(2570752K), 0.0377806 secs] [Times: user=0.16 sys=0.06, real=0.04 secs] [GC (Allocation Failure) [PSYoungGen: 1043536K->85568K(1182720K)] 2039914K->1140048K(2580992K), 0.0504137 secs] [Times: user=0.22 sys=0.13, real=0.05 secs] [GC (Allocation Failure) [PSYoungGen: 1080384K->88928K(1185280K)] 2134864K->1208335K(2583552K), 0.0468659 secs] [Times: user=0.23 sys=0.11, real=0.05 secs] DEBUG 2016-07-26T08:30:08.871Z RootLogger Thread-9 DXF [Layers [220] Blocks [255] Entities [38309] LWPolyline [1630] LW2DVertex [11854] Bounds [39447] Quads [668039]] Process [Interval [10000] Timer [Started [2016:07:26 09:29:58] Running Elapsed [10001ms]]] [GC (Allocation Failure) [PSYoungGen: 1083744K->84224K(1196544K)] 2203151K->1270900K(2594816K), 0.0492592 secs] [Times: user=0.21 sys=0.13, real=0.05 secs] [GC (Allocation Failure) [PSYoungGen: 1106176K->88992K(1200640K)] 2292852K->1339473K(2598912K), 0.0542794 secs] [Times: user=0.21 sys=0.20, real=0.05 secs] [GC (Allocation Failure) [PSYoungGen: 1110944K->83808K(1207296K)] 2361425K->1402124K(2605568K), 0.0499539 secs] [Times: user=0.22 sys=0.11, real=0.05 secs] [Full GC (Ergonomics) [PSYoungGen: 83808K->0K(1207296K)] [ParOldGen: 1318316K->1282727K(1988096K)] 1402124K->1282727K(3195392K), [Metaspace: 18575K->18575K(1067008K)], 0.5090303 secs] [Times: user=3.44 sys=0.01, real=0.51 secs] [GC (Allocation Failure) [PSYoungGen: 1044992K->90336K(1212928K)] 2327719K->1373063K(3201024K), 0.0245114 secs] [Times: user=0.17 sys=0.00, real=0.03 secs] CALL_FINALLY 2016-07-26T08:30:15.726Z org.iungo.dataset.bulkload.DXFDatasetBulkload#2 bulkload#5 Call [2016-07-26T08:30:15.726Z] [Visitor] CALL_TRY 2016-07-26T08:30:15.727Z org.iungo.dataset.bulkload.DXFDatasetBulkload#2 bulkload#5 [2016-07-26T08:30:15.726Z] [Visitor] [GC (Allocation Failure) [PSYoungGen: 1135328K->53984K(1217536K)] 2418055K->1405913K(3205632K), 0.0471537 secs] [Times: user=0.24 sys=0.07, real=0.05 secs] DEBUG 2016-07-26T08:30:18.870Z RootLogger Thread-9 DXF [Layers [424] Blocks [439] Entities [86599] LWPolyline [2112] LW2DVertex [14845] Bounds [88974] Quads [1421451]] Process [Interval [10000] Timer [Started [2016:07:26 09:29:58] Running Elapsed [20001ms]]] [GC (Allocation Failure) [PSYoungGen: 1119456K->50912K(1224704K)] 2471385K->1443866K(3212800K), 0.0396251 secs] [Times: user=0.20 sys=0.08, real=0.04 secs] [GC (Allocation Failure) [PSYoungGen: 1116384K->59328K(1224704K)] 2509338K->1490447K(3212800K), 0.0453817 secs] [Times: user=0.26 sys=0.07, real=0.05 secs] [GC (Allocation Failure) [PSYoungGen: 1143232K->65248K(1232896K)] 2574351K->1541287K(3220992K), 0.0435746 secs] [Times: user=0.24 sys=0.05, real=0.05 secs] [GC (Allocation Failure) [PSYoungGen: 1149152K->57792K(1237504K)] 2625191K->1583621K(3225600K), 0.0448676 secs] [Times: user=0.22 sys=0.13, real=0.04 secs] [GC (Allocation Failure) [PSYoungGen: 1164736K->62912K(1243648K)] 2690565K->1632705K(3231744K), 0.0442824 secs] [Times: user=0.27 sys=0.03, real=0.05 secs] CALL_FINALLY 2016-07-26T08:30:27.809Z org.iungo.dataset.bulkload.DXFDatasetBulkload#2 bulkload#5 Call [2016-07-26T08:30:27.809Z] [Visitor] CALL_TRY 2016-07-26T08:30:27.809Z org.iungo.dataset.bulkload.DXFDatasetBulkload#2 bulkload#5 [2016-07-26T08:30:27.809Z] [Dataset commit] DEBUG 2016-07-26T08:30:28.870Z RootLogger Thread-9 DXF [Layers [440] Blocks [878] Entities [137566] LWPolyline [3998] LW2DVertex [27550] Bounds [141908] Quads [2203968]] Process [Interval [10000] Timer [Started [2016:07:26 09:29:58] Running Elapsed [30001ms]]] [GC (Allocation Failure) [PSYoungGen: 1169856K->46720K(1255424K)] 2739649K->1663932K(3243520K), 0.0501241 secs] [Times: user=0.30 sys=0.06, real=0.05 secs] [GC (Allocation Failure) [PSYoungGen: 1176704K->32064K(1258496K)] 2793916K->1685111K(3246592K), 0.0601839 secs] [Times: user=0.38 sys=0.08, real=0.06 secs] CALL_FINALLY 2016-07-26T08:30:33.971Z org.iungo.dataset.bulkload.DXFDatasetBulkload#2 bulkload#5 Call [2016-07-26T08:30:33.971Z] [Dataset commit] DEBUG 2016-07-26T08:30:33.972Z RootLogger Thread-5 DXF [Layers [440] Blocks [878] Entities [137566] LWPolyline [3998] LW2DVertex [27550] Bounds [141908] Quads [2203968]] Process [Interval [10000] Timer [Started [2016:07:26 09:29:58] Stopped [2016:07:26 09:30:33] Elapsed [35102ms]]] CALL_TRY 2016-07-26T08:30:33.972Z org.iungo.dataset.bulkload.DXFDatasetBulkload#2 bulkload#5 [2016-07-26T08:30:33.972Z] [Dataset end] DEBUG 2016-07-26T08:30:33.972Z RootLogger Thread-5 take() CALL_FINALLY 2016-07-26T08:30:33.972Z org.iungo.dataset.bulkload.DXFDatasetBulkload#2 bulkload#5 Call [2016-07-26T08:30:33.972Z] [Dataset end] FINALLY_BLOCK 2016-07-26T08:30:33.972Z org.iungo.dataset.bulkload.DXFDatasetBulkload#2 bulkload#5 Finally RETURN 2016-07-26T08:30:33.972Z org.iungo.dataset.bulkload.DXFDatasetBulkload#2 bulkload#5 Return Timer [Started [2016:07:26 09:29:57] Stopped [2016:07:26 09:30:33] Elapsed [36122ms]] Value [org.iungo.result.Result] VARIABLE 2016-07-26T08:30:33.973Z org.iungo.dataset.bulkload.DXFDatasetBulkload#2 bulkload#5 Return Value [true [DXF [Layers [440] Blocks [878] Entities [137566] LWPolyline [3998] LW2DVertex [27550] Bounds [141908] Quads [2203968]] Timer [Interval [10000] Timer [Started [2016:07:26 09:29:58] Stopped [2016:07:26 09:30:33] Elapsed [35102ms]]]] [java.lang.String]] iungo runtime true Processors [8] Memory MB [Total [3170(87%)] Free [743(23%)] Max [3641]] (No value returned)iungo gc [GC (System.gc()) [PSYoungGen: 831864K->24096K(1269248K)] 2484911K->1703087K(3257344K), 0.0730718 secs] [Times: user=0.49 sys=0.01, real=0.07 secs] [Full GC (System.gc()) [PSYoungGen: 24096K->0K(1269248K)] [ParOldGen: 1678991K->1580464K(1988096K)] 1703087K->1580464K(3257344K), [Metaspace: 18575K->18575K(1067008K)], 0.5331020 secs] [Times: user=3.27 sys=0.01, real=0.54 secs] true Before [Processors [8] Memory MB [Total [3170(87%)] Free [743(23%)] Max [3641]]] After [Processors [8] Memory MB [Total [3181(87%)] Free [1634(51%)] Max [3641]]] (No value returned)WARN 2016-07-26T08:31:06.089Z RootLogger Finalizer Return value not called [Logger [Logger [org.iungo.logger.SystemLogger] Name [org.iungo.dataset.bulkload.DXFDatasetBulkload#2] Level [ALL] Counts [26/26/0]] Name [bulkload#5] Timer [Started [2016:07:26 09:29:57] Stopped [2016:07:26 09:30:33] Elapsed [36122ms]]] dataset node "TDB" bulkload source type "image/vnd.dxf" url "file:///home/dick/eclipse-jee-neon/git/iungo-ssl/iungo-ssl/test/resources/0005_XXXX-SSL-XXX-XX-DR-U-0200.dxf" METHOD 2016-07-26T08:31:12.475Z org.iungo.dataset.tdb.node.TDBDatasetNode#TDB bulkload#6 org.iungo.result.Result bulkload(org.iungo.context.Context) true Added bulkload org.iungo.queue.EntryDEBUG 2016-07-26T08:31:12.475Z RootLogger Thread-5 process ([ID [87d72201-6f16-45f8-b076-7448b50d35ba] Result [null]]) RETURN 2016-07-26T08:31:12.475Z org.iungo.dataset.tdb.node.TDBDatasetNode#TDB bulkload#6 Return Timer [Started [2016:07:26 09:31:12] Stopped [2016:07:26 09:31:12] Elapsed [0ms]] Value [org.iungo.result.Result] VARIABLE 2016-07-26T08:31:12.476Z org.iungo.dataset.tdb.node.TDBDatasetNode#TDB bulkload#6 Return Value [true [Added bulkload] [org.iungo.queue.Entry]] DEBUG 2016-07-26T08:31:12.476Z RootLogger Thread-5 org.iungo.lang.ClassUtils.create(org.iungo.dataset.bulkload.DXFDatasetBulkload, [Ljava.lang.Class;@71472638, [Ljava.lang.Object;@6dbb2118) INFO 2016-07-26T08:31:12.476Z RootLogger org.iungo.logger.AbstractLogger#6 Started [Logger [org.iungo.logger.SystemLogger] Name [org.iungo.dataset.bulkload.DXFDatasetBulkload#3] Level [ALL] Counts [1/0/0]] INFO 2016-07-26T08:31:12.477Z org.iungo.dataset.bulkload.DXFDatasetBulkload#3 Set level to [ALL] METHOD 2016-07-26T08:31:12.477Z org.iungo.dataset.bulkload.DXFDatasetBulkload#3 bulkload#7 org.iungo.result.Result bulkload(org.iungo.context.Context) TRY_BLOCK 2016-07-26T08:31:12.477Z org.iungo.dataset.bulkload.DXFDatasetBulkload#3 bulkload#7 Try [null] TRY_BLOCK 2016-07-26T08:31:12.477Z org.iungo.dataset.bulkload.DXFDatasetBulkload#3 bulkload#7 Try [URL input stream] CALL_TRY 2016-07-26T08:31:12.477Z org.iungo.dataset.bulkload.DXFDatasetBulkload#3 bulkload#7 [2016-07-26T08:31:12.477Z] [DXF Parser parse] CALL_FINALLY 2016-07-26T08:31:13.019Z org.iungo.dataset.bulkload.DXFDatasetBulkload#3 bulkload#7 Call [2016-07-26T08:31:13.019Z] [DXF Parser parse] CALL_TRY 2016-07-26T08:31:13.020Z org.iungo.dataset.bulkload.DXFDatasetBulkload#3 bulkload#7 [2016-07-26T08:31:13.019Z] [sizeOf(Object)#Object] CALL_FINALLY 2016-07-26T08:31:13.020Z org.iungo.dataset.bulkload.DXFDatasetBulkload#3 bulkload#7 Call [2016-07-26T08:31:13.019Z] [sizeOf(Object)#Object] CALL_TRY 2016-07-26T08:31:13.020Z org.iungo.dataset.bulkload.DXFDatasetBulkload#3 bulkload#7 [2016-07-26T08:31:13.019Z] [sizeOf(Object)#References] CALL_FINALLY 2016-07-26T08:31:13.459Z org.iungo.dataset.bulkload.DXFDatasetBulkload#3 bulkload#7 Call [2016-07-26T08:31:13.459Z] [sizeOf(Object)#References] SIZE_OF 2016-07-26T08:31:13.459Z org.iungo.dataset.bulkload.DXFDatasetBulkload#3 bulkload#7 Variable [draftDocument] = [72/27324264] VARIABLE 2016-07-26T08:31:13.459Z org.iungo.dataset.bulkload.DXFDatasetBulkload#3 bulkload#7 Variable [g] = [urn:iungo:dxf/graph/b5a430eb-65f0-458b-91f7-aae611d358e9] CALL_TRY 2016-07-26T08:31:13.459Z org.iungo.dataset.bulkload.DXFDatasetBulkload#3 bulkload#7 [2016-07-26T08:31:13.459Z] [Dataset write] CALL_FINALLY 2016-07-26T08:31:13.461Z org.iungo.dataset.bulkload.DXFDatasetBulkload#3 bulkload#7 Call [2016-07-26T08:31:13.461Z] [Dataset write] DEBUG 2016-07-26T08:31:13.461Z RootLogger Thread-5 DXF [Layers [0] Blocks [0] Entities [0] LWPolyline [0] LW2DVertex [0] Bounds [0] Quads [0]] Process [Interval [10000] Timer [Started [2016:07:26 09:31:13] Running Elapsed [0ms]]] TRY_BLOCK 2016-07-26T08:31:13.461Z org.iungo.dataset.bulkload.DXFDatasetBulkload#3 bulkload#7 Try [Visitor] CALL_TRY 2016-07-26T08:31:13.463Z org.iungo.dataset.bulkload.DXFDatasetBulkload#3 bulkload#7 [2016-07-26T08:31:13.463Z] [Visitor] [GC (Allocation Failure) [PSYoungGen: 1140736K->58401K(1199616K)] 2721200K->1638873K(3187712K), 0.0203087 secs] [Times: user=0.13 sys=0.00, real=0.02 secs] WARN 2016-07-26T08:31:13.926Z RootLogger Finalizer Return value not called [Logger [Logger [org.iungo.logger.SystemLogger] Name [org.iungo.dataset.tdb.node.TDBDatasetNode#TDB] Level [INFO] Counts [9/9/0]] Name [bulkload#6] Timer [Started [2016:07:26 09:31:12] Stopped [2016:07:26 09:31:12] Elapsed [0ms]]] [GC (Allocation Failure) [PSYoungGen: 1199137K->121328K(1185280K)] 2779609K->1779577K(3173376K), 0.0556827 secs] [Times: user=0.36 sys=0.05, real=0.06 secs] [GC (Allocation Failure) [PSYoungGen: 1185264K->105408K(1169408K)] 2843513K->1859014K(3157504K), 0.0643966 secs] [Times: user=0.27 sys=0.20, real=0.07 secs] [GC (Allocation Failure) [PSYoungGen: 1169344K->102592K(1227776K)] 2922950K->1935821K(3215872K), 0.0544275 secs] [Times: user=0.25 sys=0.13, real=0.06 secs] [GC (Allocation Failure) [PSYoungGen: 1160384K->113184K(1171456K)] 2993613K->2023999K(3159552K), 0.0517638 secs] [Times: user=0.19 sys=0.13, real=0.06 secs] [Full GC (Ergonomics) [PSYoungGen: 113184K->0K(1171456K)] [ParOldGen: 1910815K->1912144K(2796544K)] 2023999K->1912144K(3968000K), [Metaspace: 18577K->18577K(1067008K)], 0.4101127 secs] [Times: user=3.02 sys=0.00, real=0.40 secs] DEBUG 2016-07-26T08:31:23.461Z RootLogger Thread-11 DXF [Layers [220] Blocks [211] Entities [36397] LWPolyline [1435] LW2DVertex [10876] Bounds [37380] Quads [636022]] Process [Interval [10000] Timer [Started [2016:07:26 09:31:13] Running Elapsed [10001ms]]] [GC (Allocation Failure) [PSYoungGen: 1057792K->97376K(1227264K)] 2969936K->2009520K(4023808K), 0.0267507 secs] [Times: user=0.16 sys=0.00, real=0.03 secs] [GC (Allocation Failure) [PSYoungGen: 1151072K->101312K(1155072K)] 3063216K->2087266K(3951616K), 0.0558575 secs] [Times: user=0.26 sys=0.13, real=0.05 secs] [GC (Allocation Failure) [PSYoungGen: 1155008K->96512K(1225728K)] 3140962K->2159487K(4022272K), 0.0580832 secs] [Times: user=0.30 sys=0.13, real=0.05 secs] [GC (Allocation Failure) [PSYoungGen: 1154304K->82336K(1221632K)] 3217279K->2219090K(4018176K), 0.0567664 secs] [Times: user=0.24 sys=0.12, real=0.06 secs] [GC (Allocation Failure) [PSYoungGen: 1140128K->95968K(1226752K)] 3276882K->2294688K(4023296K), 0.0685312 secs] [Times: user=0.31 sys=0.20, real=0.07 secs] CALL_FINALLY 2016-07-26T08:31:30.719Z org.iungo.dataset.bulkload.DXFDatasetBulkload#3 bulkload#7 Call [2016-07-26T08:31:30.719Z] [Visitor] CALL_TRY 2016-07-26T08:31:30.719Z org.iungo.dataset.bulkload.DXFDatasetBulkload#3 bulkload#7 [2016-07-26T08:31:30.719Z] [Visitor] [GC (Allocation Failure) [PSYoungGen: 1165536K->54368K(1223168K)] 3364256K->2326061K(4019712K), 0.0587577 secs] [Times: user=0.25 sys=0.13, real=0.06 secs] DEBUG 2016-07-26T08:31:33.461Z RootLogger Thread-11 DXF [Layers [423] Blocks [439] Entities [83173] LWPolyline [2112] LW2DVertex [14845] Bounds [85547] Quads [1360158]] Process [Interval [10000] Timer [Started [2016:07:26 09:31:13] Running Elapsed [20000ms]]] [GC (Allocation Failure) [PSYoungGen: 1123936K->42656K(1239552K)] 3395629K->2355614K(4036096K), 0.0509542 secs] [Times: user=0.21 sys=0.13, real=0.05 secs] [GC (Allocation Failure) [PSYoungGen: 1129632K->48320K(1239552K)] 3442590K->2392905K(4036096K), 0.0319827 secs] [Times: user=0.16 sys=0.06, real=0.03 secs] [GC (Allocation Failure) [PSYoungGen: 1135296K->58720K(1239040K)] 3479881K->2439459K(4035584K), 0.0351797 secs] [Times: user=0.19 sys=0.06, real=0.04 secs] [GC (Allocation Failure) [PSYoungGen: 1153376K->55392K(1241088K)] 3534115K->2480817K(4037632K), 0.0389223 secs] [Times: user=0.21 sys=0.06, real=0.04 secs] [GC (Allocation Failure) [PSYoungGen: 1150048K->52352K(1245696K)] 3575473K->2519604K(4042240K), 0.0403291 secs] [Times: user=0.18 sys=0.08, real=0.04 secs] [GC (Allocation Failure) [PSYoungGen: 1160832K->54112K(1247744K)] 3628084K->2560955K(4044288K), 0.0351433 secs] [Times: user=0.21 sys=0.04, real=0.04 secs] DEBUG 2016-07-26T08:31:43.461Z RootLogger Thread-11 DXF [Layers [440] Blocks [877] Entities [137515] LWPolyline [3996] LW2DVertex [27538] Bounds [141851] Quads [2201819]] Process [Interval [10000] Timer [Started [2016:07:26 09:31:13] Running Elapsed [30000ms]]] CALL_FINALLY 2016-07-26T08:31:43.556Z org.iungo.dataset.bulkload.DXFDatasetBulkload#3 bulkload#7 Call [2016-07-26T08:31:43.556Z] [Visitor] CALL_TRY 2016-07-26T08:31:43.556Z org.iungo.dataset.bulkload.DXFDatasetBulkload#3 bulkload#7 [2016-07-26T08:31:43.556Z] [Dataset commit] [GC (Allocation Failure) [PSYoungGen: 1162592K->46656K(1255424K)] 3669435K->2594228K(4051968K), 0.0512520 secs] [Times: user=0.34 sys=0.04, real=0.06 secs] [GC (Allocation Failure) [PSYoungGen: 1169984K->31680K(1255936K)] 3717556K->2614996K(4052480K), 0.0546956 secs] [Times: user=0.33 sys=0.10, real=0.05 secs] CALL_FINALLY 2016-07-26T08:31:49.964Z org.iungo.dataset.bulkload.DXFDatasetBulkload#3 bulkload#7 Call [2016-07-26T08:31:49.964Z] [Dataset commit] DEBUG 2016-07-26T08:31:49.964Z RootLogger Thread-5 DXF [Layers [440] Blocks [878] Entities [137566] LWPolyline [3998] LW2DVertex [27550] Bounds [141908] Quads [2203968]] Process [Interval [10000] Timer [Started [2016:07:26 09:31:13] Stopped [2016:07:26 09:31:49] Elapsed [36503ms]]] CALL_TRY 2016-07-26T08:31:49.965Z org.iungo.dataset.bulkload.DXFDatasetBulkload#3 bulkload#7 [2016-07-26T08:31:49.965Z] [Dataset end] DEBUG 2016-07-26T08:31:49.965Z RootLogger Thread-5 take() CALL_FINALLY 2016-07-26T08:31:49.965Z org.iungo.dataset.bulkload.DXFDatasetBulkload#3 bulkload#7 Call [2016-07-26T08:31:49.965Z] [Dataset end] FINALLY_BLOCK 2016-07-26T08:31:49.965Z org.iungo.dataset.bulkload.DXFDatasetBulkload#3 bulkload#7 Finally RETURN 2016-07-26T08:31:49.965Z org.iungo.dataset.bulkload.DXFDatasetBulkload#3 bulkload#7 Return Timer [Started [2016:07:26 09:31:12] Stopped [2016:07:26 09:31:49] Elapsed [37489ms]] Value [org.iungo.result.Result] VARIABLE 2016-07-26T08:31:49.965Z org.iungo.dataset.bulkload.DXFDatasetBulkload#3 bulkload#7 Return Value [true [DXF [Layers [440] Blocks [878] Entities [137566] LWPolyline [3998] LW2DVertex [27550] Bounds [141908] Quads [2203968]] Timer [Interval [10000] Timer [Started [2016:07:26 09:31:13] Stopped [2016:07:26 09:31:49] Elapsed [36503ms]]]] [java.lang.String]] iungo gc [GC (System.gc()) [PSYoungGen: 1048053K->29888K(1262080K)] 3631370K->2637612K(4058624K), 0.0699907 secs] [Times: user=0.49 sys=0.02, real=0.07 secs] [Full GC (System.gc()) [PSYoungGen: 29888K->0K(1262080K)] [ParOldGen: 2607724K->2481924K(2796544K)] 2637612K->2481924K(4058624K), [Metaspace: 18577K->18577K(1067008K)], 0.8021440 secs] [Times: user=5.16 sys=0.03, real=0.80 secs] true Before [Processors [8] Memory MB [Total [3957(100%)] Free [411(10%)] Max [3957]]] After [Processors [8] Memory MB [Total [3963(100%)] Free [1538(39%)] Max [3963]]] (No value returned)WARN 2016-07-26T08:32:06.132Z RootLogger Finalizer Return value not called [Logger [Logger [org.iungo.logger.SystemLogger] Name [org.iungo.dataset.bulkload.DXFDatasetBulkload#3] Level [ALL] Counts [26/26/0]] Name [bulkload#7] Timer [Started [2016:07:26 09:31:12] Stopped [2016:07:26 09:31:49] Elapsed [37489ms]]] dataset node "TDB" bulkload source type "image/vnd.dxf" url "file:///home/dick/eclipse-jee-neon/git/iungo-ssl/iungo-ssl/test/resources/0005_XXXX-SSL-XXX-XX-DR-U-0200.dxf" METHOD 2016-07-26T08:35:07.737Z org.iungo.dataset.tdb.node.TDBDatasetNode#TDB bulkload#8 org.iungo.result.Result bulkload(org.iungo.context.Context) true Added bulkload org.iungo.queue.EntryDEBUG 2016-07-26T08:35:07.738Z RootLogger Thread-5 process ([ID [464ebfd9-3a8b-4f46-af17-07079ca933de] Result [null]]) DEBUG 2016-07-26T08:35:07.738Z RootLogger Thread-5 org.iungo.lang.ClassUtils.create(org.iungo.dataset.bulkload.DXFDatasetBulkload, [Ljava.lang.Class;@44346c67, [Ljava.lang.Object;@5052bc39) INFO 2016-07-26T08:35:07.738Z RootLogger org.iungo.logger.AbstractLogger#7 Started [Logger [org.iungo.logger.SystemLogger] Name [org.iungo.dataset.bulkload.DXFDatasetBulkload#4] Level [ALL] Counts [1/0/0]] RETURN 2016-07-26T08:35:07.738Z org.iungo.dataset.tdb.node.TDBDatasetNode#TDB bulkload#8 Return Timer [Started [2016:07:26 09:35:07] Stopped [2016:07:26 09:35:07] Elapsed [1ms]] Value [org.iungo.result.Result] INFO 2016-07-26T08:35:07.738Z org.iungo.dataset.bulkload.DXFDatasetBulkload#4 Set level to [ALL] VARIABLE 2016-07-26T08:35:07.738Z org.iungo.dataset.tdb.node.TDBDatasetNode#TDB bulkload#8 Return Value [true [Added bulkload] [org.iungo.queue.Entry]] METHOD 2016-07-26T08:35:07.738Z org.iungo.dataset.bulkload.DXFDatasetBulkload#4 bulkload#9 org.iungo.result.Result bulkload(org.iungo.context.Context) TRY_BLOCK 2016-07-26T08:35:07.738Z org.iungo.dataset.bulkload.DXFDatasetBulkload#4 bulkload#9 Try [null] TRY_BLOCK 2016-07-26T08:35:07.739Z org.iungo.dataset.bulkload.DXFDatasetBulkload#4 bulkload#9 Try [URL input stream] CALL_TRY 2016-07-26T08:35:07.739Z org.iungo.dataset.bulkload.DXFDatasetBulkload#4 bulkload#9 [2016-07-26T08:35:07.739Z] [DXF Parser parse] CALL_FINALLY 2016-07-26T08:35:08.241Z org.iungo.dataset.bulkload.DXFDatasetBulkload#4 bulkload#9 Call [2016-07-26T08:35:08.241Z] [DXF Parser parse] CALL_TRY 2016-07-26T08:35:08.241Z org.iungo.dataset.bulkload.DXFDatasetBulkload#4 bulkload#9 [2016-07-26T08:35:08.241Z] [sizeOf(Object)#Object] CALL_FINALLY 2016-07-26T08:35:08.241Z org.iungo.dataset.bulkload.DXFDatasetBulkload#4 bulkload#9 Call [2016-07-26T08:35:08.241Z] [sizeOf(Object)#Object] CALL_TRY 2016-07-26T08:35:08.241Z org.iungo.dataset.bulkload.DXFDatasetBulkload#4 bulkload#9 [2016-07-26T08:35:08.241Z] [sizeOf(Object)#References] CALL_FINALLY 2016-07-26T08:35:08.634Z org.iungo.dataset.bulkload.DXFDatasetBulkload#4 bulkload#9 Call [2016-07-26T08:35:08.634Z] [sizeOf(Object)#References] SIZE_OF 2016-07-26T08:35:08.635Z org.iungo.dataset.bulkload.DXFDatasetBulkload#4 bulkload#9 Variable [draftDocument] = [72/27314624] VARIABLE 2016-07-26T08:35:08.635Z org.iungo.dataset.bulkload.DXFDatasetBulkload#4 bulkload#9 Variable [g] = [urn:iungo:dxf/graph/cf994529-31b5-4c71-a312-99a6fecd276b] CALL_TRY 2016-07-26T08:35:08.635Z org.iungo.dataset.bulkload.DXFDatasetBulkload#4 bulkload#9 [2016-07-26T08:35:08.635Z] [Dataset write] CALL_FINALLY 2016-07-26T08:35:08.636Z org.iungo.dataset.bulkload.DXFDatasetBulkload#4 bulkload#9 Call [2016-07-26T08:35:08.636Z] [Dataset write] TRY_BLOCK 2016-07-26T08:35:08.636Z org.iungo.dataset.bulkload.DXFDatasetBulkload#4 bulkload#9 Try [Visitor] DEBUG 2016-07-26T08:35:08.636Z RootLogger Thread-5 DXF [Layers [0] Blocks [0] Entities [0] LWPolyline [0] LW2DVertex [0] Bounds [0] Quads [0]] Process [Interval [10000] Timer [Started [2016:07:26 09:35:08] Running Elapsed [0ms]]] CALL_TRY 2016-07-26T08:35:08.636Z org.iungo.dataset.bulkload.DXFDatasetBulkload#4 bulkload#9 [2016-07-26T08:35:08.636Z] [Visitor] [GC (Allocation Failure) [PSYoungGen: 1133056K->57105K(1190400K)] 3614980K->2539030K(3986944K), 0.0212950 secs] [Times: user=0.14 sys=0.00, real=0.02 secs] WARN 2016-07-26T08:35:09.037Z RootLogger Finalizer Return value not called [Logger [Logger [org.iungo.logger.SystemLogger] Name [org.iungo.dataset.tdb.node.TDBDatasetNode#TDB] Level [INFO] Counts [12/12/0]] Name [bulkload#8] Timer [Started [2016:07:26 09:35:07] Stopped [2016:07:26 09:35:07] Elapsed [1ms]]] [GC (Allocation Failure) [PSYoungGen: 1190161K->124384K(1185280K)] 3672086K->2677930K(3981824K), 0.0491260 secs] [Times: user=0.37 sys=0.00, real=0.05 secs] [GC (Allocation Failure) [PSYoungGen: 1185248K->102160K(1163264K)] 3738794K->2754409K(3959808K), 0.0536836 secs] [Times: user=0.24 sys=0.14, real=0.05 secs] [GC (Allocation Failure) [PSYoungGen: 1163024K->97920K(1229824K)] 3815273K->2827108K(4026368K), 0.0502531 secs] [Times: user=0.21 sys=0.14, real=0.05 secs] [Full GC (Ergonomics) [PSYoungGen: 97920K->0K(1229824K)] [ParOldGen: 2729188K->2724606K(2796544K)] 2827108K->2724606K(4026368K), [Metaspace: 18595K->18595K(1067008K)], 0.4307318 secs] [Times: user=3.20 sys=0.00, real=0.43 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->4136K(1229824K)] [ParOldGen: 2724606K->2796543K(2796544K)] 3784958K->2800679K(4026368K), [Metaspace: 18595K->18595K(1067008K)], 0.6340951 secs] [Times: user=4.81 sys=0.05, real=0.64 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->89403K(1229824K)] [ParOldGen: 2796543K->2796516K(2796544K)] 3856895K->2885919K(4026368K), [Metaspace: 18595K->18595K(1067008K)], 0.5056083 secs] [Times: user=3.74 sys=0.00, real=0.51 secs] DEBUG 2016-07-26T08:35:18.920Z RootLogger Thread-13 DXF [Layers [220] Blocks [208] Entities [31216] LWPolyline [880] LW2DVertex [6758] Bounds [32187] Quads [547324]] Process [Interval [10000] Timer [Started [2016:07:26 09:35:08] Running Elapsed [10284ms]]] [Full GC (Ergonomics) [PSYoungGen: 1060352K->154367K(1229824K)] [ParOldGen: 2796516K->2796501K(2796544K)] 3856868K->2950869K(4026368K), [Metaspace: 18595K->18595K(1067008K)], 0.5614438 secs] [Times: user=4.15 sys=0.01, real=0.56 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->220038K(1229824K)] [ParOldGen: 2796501K->2796325K(2796544K)] 3856853K->3016363K(4026368K), [Metaspace: 18600K->18600K(1067008K)], 0.5745505 secs] [Times: user=4.30 sys=0.01, real=0.57 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->284390K(1229824K)] [ParOldGen: 2796325K->2796126K(2796544K)] 3856677K->3080516K(4026368K), [Metaspace: 18600K->18600K(1067008K)], 0.5558938 secs] [Times: user=4.08 sys=0.01, real=0.55 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->335022K(1229824K)] [ParOldGen: 2796126K->2796468K(2796544K)] 3856478K->3131491K(4026368K), [Metaspace: 18600K->18600K(1067008K)], 0.6343564 secs] [Times: user=4.72 sys=0.01, real=0.63 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->382045K(1229824K)] [ParOldGen: 2796468K->2796084K(2796544K)] 3856820K->3178130K(4026368K), [Metaspace: 18600K->18600K(1067008K)], 0.6525819 secs] [Times: user=4.90 sys=0.02, real=0.66 secs] DEBUG 2016-07-26T08:35:28.636Z RootLogger Thread-13 DXF [Layers [220] Blocks [405] Entities [59671] LWPolyline [1950] LW2DVertex [13564] Bounds [61728] Quads [979381]] Process [Interval [10000] Timer [Started [2016:07:26 09:35:08] Running Elapsed [20001ms]]] [Full GC (Ergonomics) [PSYoungGen: 1060352K->432432K(1229824K)] [ParOldGen: 2796084K->2796509K(2796544K)] 3856436K->3228941K(4026368K), [Metaspace: 18600K->18600K(1067008K)], 0.5903141 secs] [Times: user=4.29 sys=0.02, real=0.60 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->476206K(1229824K)] [ParOldGen: 2796509K->2796291K(2796544K)] 3856861K->3272497K(4026368K), [Metaspace: 18600K->18600K(1067008K)], 0.6317856 secs] [Times: user=4.66 sys=0.00, real=0.63 secs] CALL_FINALLY 2016-07-26T08:35:32.206Z org.iungo.dataset.bulkload.DXFDatasetBulkload#4 bulkload#9 Call [2016-07-26T08:35:32.206Z] [Visitor] CALL_TRY 2016-07-26T08:35:32.206Z org.iungo.dataset.bulkload.DXFDatasetBulkload#4 bulkload#9 [2016-07-26T08:35:32.206Z] [Visitor] [Full GC (Ergonomics) [PSYoungGen: 1060352K->495124K(1229824K)] [ParOldGen: 2796291K->2796342K(2796544K)] 3856643K->3291466K(4026368K), [Metaspace: 18600K->18600K(1067008K)], 0.7499834 secs] [Times: user=5.43 sys=0.01, real=0.75 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->510081K(1229824K)] [ParOldGen: 2796342K->2796517K(2796544K)] 3856694K->3306599K(4026368K), [Metaspace: 18600K->18600K(1067008K)], 0.4042336 secs] [Times: user=2.93 sys=0.02, real=0.40 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->525065K(1229824K)] [ParOldGen: 2796517K->2796423K(2796544K)] 3856869K->3321489K(4026368K), [Metaspace: 18600K->18600K(1067008K)], 0.4187337 secs] [Times: user=3.05 sys=0.00, real=0.42 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->539657K(1229824K)] [ParOldGen: 2796423K->2796250K(2796544K)] 3856775K->3335907K(4026368K), [Metaspace: 18600K->18600K(1067008K)], 0.4128904 secs] [Times: user=3.02 sys=0.00, real=0.41 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->555275K(1229824K)] [ParOldGen: 2796250K->2796047K(2796544K)] 3856602K->3351322K(4026368K), [Metaspace: 18600K->18600K(1067008K)], 0.4273892 secs] [Times: user=3.08 sys=0.01, real=0.43 secs] DEBUG 2016-07-26T08:35:38.786Z RootLogger Thread-13 DXF [Layers [440] Blocks [484] Entities [90453] LWPolyline [2224] LW2DVertex [16067] Bounds [92977] Quads [1494896]] Process [Interval [10000] Timer [Started [2016:07:26 09:35:08] Running Elapsed [30150ms]]] [Full GC (Ergonomics) [PSYoungGen: 1060352K->570067K(1229824K)] [ParOldGen: 2796047K->2796530K(2796544K)] 3856399K->3366597K(4026368K), [Metaspace: 18600K->18600K(1067008K)], 0.3771630 secs] [Times: user=2.67 sys=0.00, real=0.38 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->586713K(1229824K)] [ParOldGen: 2796530K->2796473K(2796544K)] 3856882K->3383186K(4026368K), [Metaspace: 18600K->18600K(1067008K)], 0.4079098 secs] [Times: user=2.94 sys=0.02, real=0.41 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->604230K(1229824K)] [ParOldGen: 2796473K->2796473K(2796544K)] 3856825K->3400703K(4026368K), [Metaspace: 18600K->18600K(1067008K)], 0.4887390 secs] [Times: user=3.29 sys=0.00, real=0.49 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->619437K(1229824K)] [ParOldGen: 2796473K->2796473K(2796544K)] 3856825K->3415910K(4026368K), [Metaspace: 18600K->18600K(1067008K)], 0.3851926 secs] [Times: user=2.72 sys=0.01, real=0.38 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->633907K(1229824K)] [ParOldGen: 2796473K->2796473K(2796544K)] 3856825K->3430380K(4026368K), [Metaspace: 18600K->18600K(1067008K)], 0.4670582 secs] [Times: user=3.03 sys=0.01, real=0.47 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->646536K(1229824K)] [ParOldGen: 2796473K->2796473K(2796544K)] 3856825K->3443010K(4026368K), [Metaspace: 18600K->18600K(1067008K)], 0.3946525 secs] [Times: user=2.76 sys=0.01, real=0.40 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->658701K(1229824K)] [ParOldGen: 2796473K->2796473K(2796544K)] 3856825K->3455175K(4026368K), [Metaspace: 18600K->18600K(1067008K)], 0.4139186 secs] [Times: user=2.96 sys=0.00, real=0.42 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->671599K(1229824K)] [ParOldGen: 2796473K->2796473K(2796544K)] 3856825K->3468072K(4026368K), [Metaspace: 18600K->18600K(1067008K)], 0.4255710 secs] [Times: user=3.10 sys=0.00, real=0.43 secs] DEBUG 2016-07-26T08:35:48.636Z RootLogger Thread-13 DXF [Layers [440] Blocks [780] Entities [124611] LWPolyline [3739] LW2DVertex [26322] Bounds [128308] Quads [2016664]] Process [Interval [10000] Timer [Started [2016:07:26 09:35:08] Running Elapsed [40000ms]]] [Full GC (Ergonomics) [PSYoungGen: 1060352K->685273K(1229824K)] [ParOldGen: 2796473K->2796473K(2796544K)] 3856825K->3481746K(4026368K), [Metaspace: 18600K->18600K(1067008K)], 0.5331408 secs] [Times: user=3.79 sys=0.02, real=0.53 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->697738K(1229824K)] [ParOldGen: 2796473K->2796473K(2796544K)] 3856825K->3494212K(4026368K), [Metaspace: 18600K->18600K(1067008K)], 0.4704802 secs] [Times: user=2.99 sys=0.01, real=0.48 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->709033K(1229824K)] [ParOldGen: 2796473K->2796473K(2796544K)] 3856825K->3505506K(4026368K), [Metaspace: 18600K->18600K(1067008K)], 0.5106929 secs] [Times: user=2.91 sys=0.01, real=0.51 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->720016K(1229824K)] [ParOldGen: 2796473K->2796473K(2796544K)] 3856825K->3516490K(4026368K), [Metaspace: 18600K->18600K(1067008K)], 0.4739230 secs] [Times: user=3.05 sys=0.00, real=0.47 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->731050K(1229824K)] [ParOldGen: 2796473K->2796473K(2796544K)] 3856825K->3527524K(4026368K), [Metaspace: 18600K->18600K(1067008K)], 0.3991563 secs] [Times: user=2.85 sys=0.00, real=0.40 secs] CALL_FINALLY 2016-07-26T08:35:53.658Z org.iungo.dataset.bulkload.DXFDatasetBulkload#4 bulkload#9 Call [2016-07-26T08:35:53.658Z] [Visitor] CALL_TRY 2016-07-26T08:35:53.658Z org.iungo.dataset.bulkload.DXFDatasetBulkload#4 bulkload#9 [2016-07-26T08:35:53.658Z] [Dataset commit] [Full GC (Ergonomics) [PSYoungGen: 1060352K->732725K(1229824K)] [ParOldGen: 2796473K->2796323K(2796544K)] 3856825K->3529049K(4026368K), [Metaspace: 18600K->18600K(1067008K)], 0.7759076 secs] [Times: user=5.61 sys=0.00, real=0.78 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->731644K(1229824K)] [ParOldGen: 2796323K->2796502K(2796544K)] 3856675K->3528146K(4026368K), [Metaspace: 18600K->18600K(1067008K)], 0.8256613 secs] [Times: user=5.72 sys=0.02, real=0.82 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->731144K(1229824K)] [ParOldGen: 2796502K->2796200K(2796544K)] 3856854K->3527344K(4026368K), [Metaspace: 18600K->18600K(1067008K)], 0.7834860 secs] [Times: user=5.63 sys=0.06, real=0.79 secs] DEBUG 2016-07-26T08:35:58.807Z RootLogger Thread-13 DXF [Layers [440] Blocks [878] Entities [137566] LWPolyline [3998] LW2DVertex [27550] Bounds [141908] Quads [2203968]] Process [Interval [10000] Timer [Started [2016:07:26 09:35:08] Running Elapsed [50171ms]]] [Full GC (Ergonomics) [PSYoungGen: 1060352K->730955K(1229824K)] [ParOldGen: 2796200K->2796193K(2796544K)] 3856552K->3527149K(4026368K), [Metaspace: 18600K->18600K(1067008K)], 0.5440818 secs] [Times: user=4.09 sys=0.02, real=0.54 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->730926K(1229824K)] [ParOldGen: 2796193K->2796210K(2796544K)] 3856545K->3527136K(4026368K), [Metaspace: 18600K->18600K(1067008K)], 0.5644173 secs] [Times: user=4.14 sys=0.00, real=0.57 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->730898K(1229824K)] [ParOldGen: 2796210K->2796357K(2796544K)] 3856562K->3527255K(4026368K), [Metaspace: 18600K->18600K(1067008K)], 0.5922727 secs] [Times: user=4.20 sys=0.00, real=0.59 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->731269K(1229824K)] [ParOldGen: 2796357K->2796103K(2796544K)] 3856709K->3527372K(4026368K), [Metaspace: 18600K->18600K(1067008K)], 0.5994868 secs] [Times: user=4.21 sys=0.00, real=0.60 secs] CALL_FINALLY 2016-07-26T08:36:03.446Z org.iungo.dataset.bulkload.DXFDatasetBulkload#4 bulkload#9 Call [2016-07-26T08:36:03.446Z] [Dataset commit] DEBUG 2016-07-26T08:36:03.446Z RootLogger Thread-5 DXF [Layers [440] Blocks [878] Entities [137566] LWPolyline [3998] LW2DVertex [27550] Bounds [141908] Quads [2203968]] Process [Interval [10000] Timer [Started [2016:07:26 09:35:08] Stopped [2016:07:26 09:36:03] Elapsed [54810ms]]] CALL_TRY 2016-07-26T08:36:03.447Z org.iungo.dataset.bulkload.DXFDatasetBulkload#4 bulkload#9 [2016-07-26T08:36:03.447Z] [Dataset end] CALL_FINALLY 2016-07-26T08:36:03.447Z org.iungo.dataset.bulkload.DXFDatasetBulkload#4 bulkload#9 Call [2016-07-26T08:36:03.447Z] [Dataset end] DEBUG 2016-07-26T08:36:03.447Z RootLogger Thread-5 take() FINALLY_BLOCK 2016-07-26T08:36:03.447Z org.iungo.dataset.bulkload.DXFDatasetBulkload#4 bulkload#9 Finally RETURN 2016-07-26T08:36:03.447Z org.iungo.dataset.bulkload.DXFDatasetBulkload#4 bulkload#9 Return Timer [Started [2016:07:26 09:35:07] Stopped [2016:07:26 09:36:03] Elapsed [55709ms]] Value [org.iungo.result.Result] VARIABLE 2016-07-26T08:36:03.447Z org.iungo.dataset.bulkload.DXFDatasetBulkload#4 bulkload#9 Return Value [true [DXF [Layers [440] Blocks [878] Entities [137566] LWPolyline [3998] LW2DVertex [27550] Bounds [141908] Quads [2203968]] Timer [Interval [10000] Timer [Started [2016:07:26 09:35:08] Stopped [2016:07:26 09:36:03] Elapsed [54810ms]]]] [java.lang.String]] dataset node "TDB" bulkload source type "image/vnd.dxf" url "file:///home/dick/eclipse-jee-neon/git/iungo-ssl/iungo-ssl/test/resources/0005_XXXX-SSL-XXX-XX-DR-U-0200.dxf" METHOD 2016-07-26T08:37:28.081Z org.iungo.dataset.tdb.node.TDBDatasetNode#TDB bulkload#10 org.iungo.result.Result bulkload(org.iungo.context.Context) true Added bulkload org.iungo.queue.EntryDEBUG 2016-07-26T08:37:28.081Z RootLogger Thread-5 process ([ID [d9d16c72-da01-4690-b5bc-6c2ea3cb9e86] Result [null]]) DEBUG 2016-07-26T08:37:28.081Z RootLogger Thread-5 org.iungo.lang.ClassUtils.create(org.iungo.dataset.bulkload.DXFDatasetBulkload, [Ljava.lang.Class;@15f6e228, [Ljava.lang.Object;@47282d40) RETURN 2016-07-26T08:37:28.081Z org.iungo.dataset.tdb.node.TDBDatasetNode#TDB bulkload#10 Return Timer [Started [2016:07:26 09:37:28] Stopped [2016:07:26 09:37:28] Elapsed [0ms]] Value [org.iungo.result.Result] VARIABLE 2016-07-26T08:37:28.082Z org.iungo.dataset.tdb.node.TDBDatasetNode#TDB bulkload#10 Return Value [true [Added bulkload] [org.iungo.queue.Entry]] INFO 2016-07-26T08:37:28.083Z RootLogger org.iungo.logger.AbstractLogger#8 Started [Logger [org.iungo.logger.SystemLogger] Name [org.iungo.dataset.bulkload.DXFDatasetBulkload#5] Level [ALL] Counts [1/0/0]] INFO 2016-07-26T08:37:28.083Z org.iungo.dataset.bulkload.DXFDatasetBulkload#5 Set level to [ALL] METHOD 2016-07-26T08:37:28.083Z org.iungo.dataset.bulkload.DXFDatasetBulkload#5 bulkload#11 org.iungo.result.Result bulkload(org.iungo.context.Context) TRY_BLOCK 2016-07-26T08:37:28.083Z org.iungo.dataset.bulkload.DXFDatasetBulkload#5 bulkload#11 Try [null] TRY_BLOCK 2016-07-26T08:37:28.083Z org.iungo.dataset.bulkload.DXFDatasetBulkload#5 bulkload#11 Try [URL input stream] CALL_TRY 2016-07-26T08:37:28.083Z org.iungo.dataset.bulkload.DXFDatasetBulkload#5 bulkload#11 [2016-07-26T08:37:28.083Z] [DXF Parser parse] [Full GC (Ergonomics) [PSYoungGen: 1060352K->634453K(1229824K)] [ParOldGen: 2796103K->2796208K(2796544K)] 3856455K->3430661K(4026368K), [Metaspace: 18624K->18624K(1067008K)], 0.4857900 secs] [Times: user=3.43 sys=0.01, real=0.49 secs] WARN 2016-07-26T08:37:28.688Z RootLogger Finalizer Return value not called [Logger [Logger [org.iungo.logger.SystemLogger] Name [org.iungo.dataset.tdb.node.TDBDatasetNode#TDB] Level [INFO] Counts [15/15/0]] Name [bulkload#10] Timer [Started [2016:07:26 09:37:28] Stopped [2016:07:26 09:37:28] Elapsed [0ms]]] WARN 2016-07-26T08:37:28.688Z RootLogger Finalizer Return value not called [Logger [Logger [org.iungo.logger.SystemLogger] Name [org.iungo.dataset.bulkload.DXFDatasetBulkload#4] Level [ALL] Counts [26/26/0]] Name [bulkload#9] Timer [Started [2016:07:26 09:35:07] Stopped [2016:07:26 09:36:03] Elapsed [55709ms]]] CALL_FINALLY 2016-07-26T08:37:29.068Z org.iungo.dataset.bulkload.DXFDatasetBulkload#5 bulkload#11 Call [2016-07-26T08:37:29.068Z] [DXF Parser parse] CALL_TRY 2016-07-26T08:37:29.068Z org.iungo.dataset.bulkload.DXFDatasetBulkload#5 bulkload#11 [2016-07-26T08:37:29.068Z] [sizeOf(Object)#Object] CALL_FINALLY 2016-07-26T08:37:29.069Z org.iungo.dataset.bulkload.DXFDatasetBulkload#5 bulkload#11 Call [2016-07-26T08:37:29.068Z] [sizeOf(Object)#Object] CALL_TRY 2016-07-26T08:37:29.069Z org.iungo.dataset.bulkload.DXFDatasetBulkload#5 bulkload#11 [2016-07-26T08:37:29.068Z] [sizeOf(Object)#References] [Full GC (Ergonomics) [PSYoungGen: 1060352K->660104K(1229824K)] [ParOldGen: 2796208K->2796206K(2796544K)] 3856560K->3456311K(4026368K), [Metaspace: 18625K->18625K(1067008K)], 0.4694237 secs] [Times: user=3.42 sys=0.00, real=0.47 secs] CALL_FINALLY 2016-07-26T08:37:29.920Z org.iungo.dataset.bulkload.DXFDatasetBulkload#5 bulkload#11 Call [2016-07-26T08:37:29.920Z] [sizeOf(Object)#References] SIZE_OF 2016-07-26T08:37:29.920Z org.iungo.dataset.bulkload.DXFDatasetBulkload#5 bulkload#11 Variable [draftDocument] = [72/27333824] VARIABLE 2016-07-26T08:37:29.920Z org.iungo.dataset.bulkload.DXFDatasetBulkload#5 bulkload#11 Variable [g] = [urn:iungo:dxf/graph/837fd0e8-f97e-43c3-8b92-dd8827db9226] CALL_TRY 2016-07-26T08:37:29.920Z org.iungo.dataset.bulkload.DXFDatasetBulkload#5 bulkload#11 [2016-07-26T08:37:29.920Z] [Dataset write] CALL_FINALLY 2016-07-26T08:37:29.921Z org.iungo.dataset.bulkload.DXFDatasetBulkload#5 bulkload#11 Call [2016-07-26T08:37:29.921Z] [Dataset write] TRY_BLOCK 2016-07-26T08:37:29.921Z org.iungo.dataset.bulkload.DXFDatasetBulkload#5 bulkload#11 Try [Visitor] DEBUG 2016-07-26T08:37:29.921Z RootLogger Thread-5 DXF [Layers [0] Blocks [0] Entities [0] LWPolyline [0] LW2DVertex [0] Bounds [0] Quads [0]] Process [Interval [10000] Timer [Started [2016:07:26 09:37:29] Running Elapsed [0ms]]] CALL_TRY 2016-07-26T08:37:29.921Z org.iungo.dataset.bulkload.DXFDatasetBulkload#5 bulkload#11 [2016-07-26T08:37:29.921Z] [Visitor] [Full GC (Ergonomics) [PSYoungGen: 1060352K->662029K(1229824K)] [ParOldGen: 2796206K->2796165K(2796544K)] 3856558K->3458194K(4026368K), [Metaspace: 18636K->18636K(1067008K)], 0.7270263 secs] [Times: user=5.42 sys=0.02, real=0.73 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->731387K(1229824K)] [ParOldGen: 2796165K->2796126K(2796544K)] 3856517K->3527514K(4026368K), [Metaspace: 18636K->18636K(1067008K)], 0.5115597 secs] [Times: user=3.83 sys=0.00, real=0.52 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->761272K(1229824K)] [ParOldGen: 2796126K->2796440K(2796544K)] 3856478K->3557713K(4026368K), [Metaspace: 18636K->18626K(1067008K)], 1.1277286 secs] [Times: user=8.34 sys=0.04, real=1.13 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->789655K(1229824K)] [ParOldGen: 2796440K->2796409K(2796544K)] 3856792K->3586065K(4026368K), [Metaspace: 18626K->18626K(1067008K)], 0.7945983 secs] [Times: user=5.81 sys=0.04, real=0.79 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->812589K(1229824K)] [ParOldGen: 2796409K->2796401K(2796544K)] 3856761K->3608990K(4026368K), [Metaspace: 18626K->18626K(1067008K)], 0.8251349 secs] [Times: user=6.26 sys=0.02, real=0.82 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->833406K(1229824K)] [ParOldGen: 2796401K->2796395K(2796544K)] 3856753K->3629801K(4026368K), [Metaspace: 18626K->18626K(1067008K)], 0.8759976 secs] [Times: user=6.60 sys=0.01, real=0.87 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->851906K(1229824K)] [ParOldGen: 2796395K->2796390K(2796544K)] 3856747K->3648297K(4026368K), [Metaspace: 18626K->18626K(1067008K)], 0.9034920 secs] [Times: user=6.75 sys=0.04, real=0.90 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->869713K(1229824K)] [ParOldGen: 2796390K->2796385K(2796544K)] 3856742K->3666098K(4026368K), [Metaspace: 18626K->18626K(1067008K)], 0.8542784 secs] [Times: user=6.41 sys=0.03, real=0.85 secs] DEBUG 2016-07-26T08:37:39.921Z RootLogger Thread-15 DXF [Layers [190] Blocks [0] Entities [11352] LWPolyline [113] LW2DVertex [1070] Bounds [11542] Quads [203643]] Process [Interval [10000] Timer [Started [2016:07:26 09:37:29] Running Elapsed [10001ms]]] [Full GC (Ergonomics) [PSYoungGen: 1060352K->884338K(1229824K)] [ParOldGen: 2796385K->2796380K(2796544K)] 3856737K->3680719K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.9539835 secs] [Times: user=7.09 sys=0.02, real=0.95 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->899372K(1229824K)] [ParOldGen: 2796380K->2796373K(2796544K)] 3856732K->3695745K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.9115765 secs] [Times: user=6.81 sys=0.03, real=0.91 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->912688K(1229824K)] [ParOldGen: 2796373K->2796366K(2796544K)] 3856725K->3709054K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.8182557 secs] [Times: user=6.12 sys=0.02, real=0.82 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->924573K(1229824K)] [ParOldGen: 2796366K->2796361K(2796544K)] 3856718K->3720934K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.8474470 secs] [Times: user=6.37 sys=0.03, real=0.85 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->935645K(1229824K)] [ParOldGen: 2796361K->2796357K(2796544K)] 3856713K->3732002K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.9291745 secs] [Times: user=6.95 sys=0.04, real=0.93 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->945499K(1229824K)] [ParOldGen: 2796357K->2796354K(2796544K)] 3856709K->3741854K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.8776748 secs] [Times: user=6.52 sys=0.03, real=0.88 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->954858K(1229824K)] [ParOldGen: 2796354K->2796350K(2796544K)] 3856706K->3751209K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.9409550 secs] [Times: user=7.08 sys=0.03, real=0.95 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->963198K(1229824K)] [ParOldGen: 2796350K->2796348K(2796544K)] 3856702K->3759546K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.8486727 secs] [Times: user=6.39 sys=0.01, real=0.84 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->970783K(1229824K)] [ParOldGen: 2796348K->2796346K(2796544K)] 3856700K->3767129K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.8557959 secs] [Times: user=6.46 sys=0.01, real=0.86 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->977965K(1229824K)] [ParOldGen: 2796346K->2796343K(2796544K)] 3856698K->3774308K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.9415255 secs] [Times: user=7.12 sys=0.00, real=0.94 secs] DEBUG 2016-07-26T08:37:50.791Z RootLogger Thread-15 DXF [Layers [206] Blocks [0] Entities [18020] LWPolyline [113] LW2DVertex [1070] Bounds [18225] Quads [323131]] Process [Interval [10000] Timer [Started [2016:07:26 09:37:29] Running Elapsed [20870ms]]] [Full GC (Ergonomics) [PSYoungGen: 1060352K->984279K(1229824K)] [ParOldGen: 2796343K->2796341K(2796544K)] 3856695K->3780620K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.9347525 secs] [Times: user=6.96 sys=0.02, real=0.93 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->990255K(1229824K)] [ParOldGen: 2796341K->2796339K(2796544K)] 3856693K->3786595K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.9520571 secs] [Times: user=7.11 sys=0.02, real=0.95 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->995623K(1229824K)] [ParOldGen: 2796339K->2796337K(2796544K)] 3856691K->3791960K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.9310927 secs] [Times: user=6.64 sys=0.03, real=0.94 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->1000588K(1229824K)] [ParOldGen: 2796337K->2796335K(2796544K)] 3856689K->3796924K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.8826194 secs] [Times: user=6.51 sys=0.01, real=0.88 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->1005364K(1229824K)] [ParOldGen: 2796335K->2796334K(2796544K)] 3856687K->3801699K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.9608125 secs] [Times: user=7.05 sys=0.01, real=0.97 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->1009414K(1229824K)] [ParOldGen: 2796334K->2796333K(2796544K)] 3856686K->3805747K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.9711567 secs] [Times: user=6.94 sys=0.03, real=0.97 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->1013627K(1229824K)] [ParOldGen: 2796333K->2796332K(2796544K)] 3856685K->3809959K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.9274380 secs] [Times: user=6.95 sys=0.01, real=0.93 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->1017445K(1229824K)] [ParOldGen: 2796332K->2796331K(2796544K)] 3856684K->3813776K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.8895476 secs] [Times: user=6.36 sys=0.03, real=0.89 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->1020287K(1229824K)] [ParOldGen: 2796331K->2796330K(2796544K)] 3856683K->3816617K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.8152140 secs] [Times: user=6.12 sys=0.01, real=0.82 secs] DEBUG 2016-07-26T08:38:00.209Z RootLogger Thread-15 DXF [Layers [212] Blocks [0] Entities [20918] LWPolyline [181] LW2DVertex [1750] Bounds [21129] Quads [378143]] Process [Interval [10000] Timer [Started [2016:07:26 09:37:29] Running Elapsed [30288ms]]] [Full GC (Ergonomics) [PSYoungGen: 1060352K->1023334K(1229824K)] [ParOldGen: 2796330K->2796322K(2796544K)] 3856682K->3819657K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.9673286 secs] [Times: user=7.00 sys=0.05, real=0.96 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->1026701K(1229824K)] [ParOldGen: 2796322K->2796319K(2796544K)] 3856674K->3823020K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.8716560 secs] [Times: user=6.17 sys=0.01, real=0.87 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->1029198K(1229824K)] [ParOldGen: 2796319K->2796317K(2796544K)] 3856671K->3825515K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.9958862 secs] [Times: user=7.05 sys=0.03, real=0.99 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->1031541K(1229824K)] [ParOldGen: 2796317K->2796315K(2796544K)] 3856669K->3827856K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.9095475 secs] [Times: user=6.17 sys=0.03, real=0.91 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->1033860K(1229824K)] [ParOldGen: 2796315K->2796313K(2796544K)] 3856667K->3830174K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 1.0211152 secs] [Times: user=7.49 sys=0.02, real=1.02 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->1035868K(1229824K)] [ParOldGen: 2796313K->2796311K(2796544K)] 3856665K->3832179K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.9288378 secs] [Times: user=6.84 sys=0.01, real=0.93 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->1037782K(1229824K)] [ParOldGen: 2796311K->2796310K(2796544K)] 3856663K->3834092K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.9366751 secs] [Times: user=7.03 sys=0.01, real=0.93 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->1039590K(1229824K)] [ParOldGen: 2796310K->2796308K(2796544K)] 3856662K->3835899K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.8240543 secs] [Times: user=6.13 sys=0.02, real=0.83 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->1041128K(1229824K)] [ParOldGen: 2796308K->2796307K(2796544K)] 3856660K->3837436K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.9203202 secs] [Times: user=6.90 sys=0.02, real=0.92 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->1042578K(1229824K)] [ParOldGen: 2796307K->2796306K(2796544K)] 3856659K->3838885K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.8958402 secs] [Times: user=6.70 sys=0.04, real=0.90 secs] DEBUG 2016-07-26T08:38:09.968Z RootLogger Thread-15 DXF [Layers [220] Blocks [125] Entities [22399] LWPolyline [225] LW2DVertex [2292] Bounds [22993] Quads [405217]] Process [Interval [10000] Timer [Started [2016:07:26 09:37:29] Running Elapsed [40047ms]]] [Full GC (Ergonomics) [PSYoungGen: 1060352K->1043759K(1229824K)] [ParOldGen: 2796306K->2796305K(2796544K)] 3856658K->3840064K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.7587285 secs] [Times: user=5.68 sys=0.02, real=0.76 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->1044959K(1229824K)] [ParOldGen: 2796305K->2796304K(2796544K)] 3856657K->3841264K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.8307296 secs] [Times: user=6.15 sys=0.01, real=0.83 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->1046075K(1229824K)] [ParOldGen: 2796304K->2796303K(2796544K)] 3856656K->3842379K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.7428160 secs] [Times: user=5.47 sys=0.02, real=0.75 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->1047051K(1229824K)] [ParOldGen: 2796303K->2796303K(2796544K)] 3856655K->3843354K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.8363360 secs] [Times: user=6.22 sys=0.06, real=0.84 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->1047949K(1229824K)] [ParOldGen: 2796303K->2796302K(2796544K)] 3856655K->3844252K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.9068747 secs] [Times: user=6.76 sys=0.01, real=0.91 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->1048827K(1229824K)] [ParOldGen: 2796302K->2796301K(2796544K)] 3856654K->3845128K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.8800083 secs] [Times: user=6.62 sys=0.01, real=0.88 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->1049840K(1229824K)] [ParOldGen: 2796301K->2796300K(2796544K)] 3856653K->3846141K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.9044757 secs] [Times: user=6.73 sys=0.03, real=0.90 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->1050652K(1229824K)] [ParOldGen: 2796300K->2796300K(2796544K)] 3856652K->3846952K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.6777164 secs] [Times: user=5.03 sys=0.01, real=0.68 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->1051357K(1229824K)] [ParOldGen: 2796300K->2796300K(2796544K)] 3856652K->3847658K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.6891479 secs] [Times: user=5.07 sys=0.01, real=0.68 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->1051977K(1229824K)] [ParOldGen: 2796300K->2796300K(2796544K)] 3856652K->3848278K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.6847955 secs] [Times: user=5.11 sys=0.01, real=0.68 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->1052515K(1229824K)] [ParOldGen: 2796300K->2796300K(2796544K)] 3856652K->3848816K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.6887732 secs] [Times: user=5.13 sys=0.01, real=0.69 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->1052954K(1229824K)] [ParOldGen: 2796300K->2796299K(2796544K)] 3856652K->3849254K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.7548947 secs] [Times: user=5.58 sys=0.01, real=0.76 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->1053471K(1229824K)] [ParOldGen: 2796299K->2796299K(2796544K)] 3856651K->3849771K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.6764151 secs] [Times: user=5.04 sys=0.03, real=0.68 secs] DEBUG 2016-07-26T08:38:20.259Z RootLogger Thread-15 DXF [Layers [220] Blocks [193] Entities [23283] LWPolyline [256] LW2DVertex [2417] Bounds [24087] Quads [420321]] Process [Interval [10000] Timer [Started [2016:07:26 09:37:29] Running Elapsed [50338ms]]] [Full GC (Ergonomics) [PSYoungGen: 1060352K->1053938K(1229824K)] [ParOldGen: 2796299K->2796298K(2796544K)] 3856651K->3850236K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.7496102 secs] [Times: user=5.55 sys=0.02, real=0.74 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->1054710K(1229824K)] [ParOldGen: 2796298K->2796292K(2796544K)] 3856650K->3851002K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.7361073 secs] [Times: user=5.50 sys=0.01, real=0.73 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->1055336K(1229824K)] [ParOldGen: 2796292K->2796290K(2796544K)] 3856644K->3851626K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.7170885 secs] [Times: user=5.34 sys=0.02, real=0.72 secs] [Full GC (Ergonomics) [PSYoungGen: 1060352K->1055845K(1229824K)] [ParOldGen: 2796290K->2796176K(2796544K)] 3856642K->3852021K(4026368K), [Metaspace: 18629K->18629K(1067008K)], 0.8833491 secs] [Times: user=6.48 sys=0.03, real=0.88 secs] CALL_CATCH 2016-07-26T08:38:23.383Z org.iungo.dataset.bulkload.DXFDatasetBulkload#5 bulkload#11 java.lang.OutOfMemoryError: GC overhead limit exceeded java.nio.HeapByteBuffer.asIntBuffer(HeapByteBuffer.java:391) org.apache.jena.tdb.base.buffer.PtrBuffer.<init>(PtrBuffer.java:47) org.apache.jena.tdb.index.bplustree.BPTreeNodeMgr.formatBPTreeNode(BPTreeNodeMgr.java:259) org.apache.jena.tdb.index.bplustree.BPTreeNodeMgr.overlay(BPTreeNodeMgr.java:204) org.apache.jena.tdb.index.bplustree.BPTreeNodeMgr.access$000(BPTreeNodeMgr.java:36) org.apache.jena.tdb.index.bplustree.BPTreeNodeMgr$Block2BPTreeNode.fromBlock(BPTreeNodeMgr.java:144) org.apache.jena.tdb.index.bplustree.BPTreeNodeMgr$Block2BPTreeNode.fromBlock(BPTreeNodeMgr.java:119) org.apache.jena.tdb.base.page.PageBlockMgr.getRead(PageBlockMgr.java:68) org.apache.jena.tdb.index.bplustree.BPTreeNodeMgr.getRead(BPTreeNodeMgr.java:105) org.apache.jena.tdb.index.bplustree.BPTreeNodeMgr.getRoot(BPTreeNodeMgr.java:90) org.apache.jena.tdb.index.bplustree.BPlusTree.getRoot(BPlusTree.java:237) org.apache.jena.tdb.index.bplustree.BPlusTree.addAndReturnOld(BPlusTree.java:325) org.apache.jena.tdb.index.bplustree.BPlusTree.add(BPlusTree.java:318) org.apache.jena.tdb.store.tupletable.TupleIndexRecord.performAdd(TupleIndexRecord.java:60) org.apache.jena.tdb.store.tupletable.TupleIndexBase.add(TupleIndexBase.java:62) org.apache.jena.tdb.store.tupletable.TupleTable.add(TupleTable.java:95) org.apache.jena.tdb.store.nodetupletable.NodeTupleTableConcrete.addRow(NodeTupleTableConcrete.java:88) org.apache.jena.tdb.store.QuadTable.add(QuadTable.java:60) org.apache.jena.tdb.store.DatasetGraphTDB.addToNamedGraph(DatasetGraphTDB.java:98) org.apache.jena.sparql.core.DatasetGraphTriplesQuads.add(DatasetGraphTriplesQuads.java:49) org.apache.jena.sparql.core.DatasetGraphWrapper.add(DatasetGraphWrapper.java:106) org.iungo.dataset.bulkload.DXFDatasetBulkload$2.visit(DXFDatasetBulkload.java:340) org.iungo.dataset.bulkload.DXFDatasetBulkload$2.visit(DXFDatasetBulkload.java:355) org.kabeja.entities.Entity.accept(Entity.java:67) org.iungo.dataset.bulkload.DXFDatasetBulkload$2.visit(DXFDatasetBulkload.java:312) org.kabeja.common.Block.accept(Block.java:59) org.iungo.dataset.bulkload.DXFDatasetBulkload$2.visit(DXFDatasetBulkload.java:197) org.kabeja.DraftDocument.accept(DraftDocument.java:100) org.iungo.dataset.bulkload.DXFDatasetBulkload$6.get(DXFDatasetBulkload.java:503) org.iungo.dataset.bulkload.DXFDatasetBulkload$6.get(DXFDatasetBulkload.java:1) org.iungo.logger.MethodLogger.call(MethodLogger.java:104) org.iungo.dataset.bulkload.DXFDatasetBulkload.bulkload(DXFDatasetBulkload.java:500) CALL_FINALLY 2016-07-26T08:38:23.384Z org.iungo.dataset.bulkload.DXFDatasetBulkload#5 bulkload#11 Call [2016-07-26T08:38:23.383Z] [Visitor] CALL_TRY 2016-07-26T08:38:23.386Z org.iungo.dataset.bulkload.DXFDatasetBulkload#5 bulkload#11 [2016-07-26T08:38:23.386Z] [Dataset abort] CALL_FINALLY 2016-07-26T08:38:23.392Z org.iungo.dataset.bulkload.DXFDatasetBulkload#5 bulkload#11 Call [2016-07-26T08:38:23.392Z] [Dataset abort] [Full GC (Ergonomics) [PSYoungGen: 1060352K->1046588K(1229824K)] [ParOldGen: 2796176K->2796174K(2796544K)] 3856528K->3842763K(4026368K), [Metaspace: 18632K->18632K(1067008K)], 0.7879990 secs] [Times: user=5.76 sys=0.03, real=0.79 secs] CATCH_BLOCK 2016-07-26T08:38:24.180Z org.iungo.dataset.bulkload.DXFDatasetBulkload#5 bulkload#11 Catch [java.lang.UnsupportedOperationException: java.lang.OutOfMemoryError: GC overhead limit exceeded org.iungo.logger.MethodLogger.call(MethodLogger.java:107) org.iungo.dataset.bulkload.DXFDatasetBulkload.bulkload(DXFDatasetBulkload.java:500) org.iungo.dataset.node.DatasetNode$1$1.accept(DatasetNode.java:222) org.iungo.dataset.node.DatasetNode$1$1.accept(DatasetNode.java:1) org.iungo.queue.Q.process(Q.java:64) org.iungo.queue.Q$1.run(Q.java:45) java.lang.Thread.run(Thread.java:745)Cause: java.lang.OutOfMemoryError: GC overhead limit exceeded java.nio.HeapByteBuffer.asIntBuffer(HeapByteBuffer.java:391) org.apache.jena.tdb.base.buffer.PtrBuffer.<init>(PtrBuffer.java:47) org.apache.jena.tdb.index.bplustree.BPTreeNodeMgr.formatBPTreeNode(BPTreeNodeMgr.java:259) org.apache.jena.tdb.index.bplustree.BPTreeNodeMgr.overlay(BPTreeNodeMgr.java:204) org.apache.jena.tdb.index.bplustree.BPTreeNodeMgr.access$000(BPTreeNodeMgr.java:36) org.apache.jena.tdb.index.bplustree.BPTreeNodeMgr$Block2BPTreeNode.fromBlock(BPTreeNodeMgr.java:144) org.apache.jena.tdb.index.bplustree.BPTreeNodeMgr$Block2BPTreeNode.fromBlock(BPTreeNodeMgr.java:119) org.apache.jena.tdb.base.page.PageBlockMgr.getRead(PageBlockMgr.java:68) org.apache.jena.tdb.index.bplustree.BPTreeNodeMgr.getRead(BPTreeNodeMgr.java:105) org.apache.jena.tdb.index.bplustree.BPTreeNodeMgr.getRoot(BPTreeNodeMgr.java:90) org.apache.jena.tdb.index.bplustree.BPlusTree.getRoot(BPlusTree.java:237) org.apache.jena.tdb.index.bplustree.BPlusTree.addAndReturnOld(BPlusTree.java:325) org.apache.jena.tdb.index.bplustree.BPlusTree.add(BPlusTree.java:318) org.apache.jena.tdb.store.tupletable.TupleIndexRecord.performAdd(TupleIndexRecord.java:60) org.apache.jena.tdb.store.tupletable.TupleIndexBase.add(TupleIndexBase.java:62) org.apache.jena.tdb.store.tupletable.TupleTable.add(TupleTable.java:95) org.apache.jena.tdb.store.nodetupletable.NodeTupleTableConcrete.addRow(NodeTupleTableConcrete.java:88) org.apache.jena.tdb.store.QuadTable.add(QuadTable.java:60) org.apache.jena.tdb.store.DatasetGraphTDB.addToNamedGraph(DatasetGraphTDB.java:98) org.apache.jena.sparql.core.DatasetGraphTriplesQuads.add(DatasetGraphTriplesQuads.java:49) org.apache.jena.sparql.core.DatasetGraphWrapper.add(DatasetGraphWrapper.java:106) org.iungo.dataset.bulkload.DXFDatasetBulkload$2.visit(DXFDatasetBulkload.java:340) org.iungo.dataset.bulkload.DXFDatasetBulkload$2.visit(DXFDatasetBulkload.java:355) org.kabeja.entities.Entity.accept(Entity.java:67) org.iungo.dataset.bulkload.DXFDatasetBulkload$2.visit(DXFDatasetBulkload.java:312) org.kabeja.common.Block.accept(Block.java:59) org.iungo.dataset.bulkload.DXFDatasetBulkload$2.visit(DXFDatasetBulkload.java:197) org.kabeja.DraftDocument.accept(DraftDocument.java:100) org.iungo.dataset.bulkload.DXFDatasetBulkload$6.get(DXFDatasetBulkload.java:503) org.iungo.dataset.bulkload.DXFDatasetBulkload$6.get(DXFDatasetBulkload.java:1) org.iungo.logger.MethodLogger.call(MethodLogger.java:104) org.iungo.dataset.bulkload.DXFDatasetBulkload.bulkload(DXFDatasetBulkload.java:500)] DEBUG 2016-07-26T08:38:24.181Z RootLogger Thread-5 take() CALL_TRY 2016-07-26T08:38:24.181Z org.iungo.dataset.bulkload.DXFDatasetBulkload#5 bulkload#11 [2016-07-26T08:38:24.180Z] [Dataset end] CALL_FINALLY 2016-07-26T08:38:24.181Z org.iungo.dataset.bulkload.DXFDatasetBulkload#5 bulkload#11 Call [2016-07-26T08:38:24.180Z] [Dataset end] FINALLY_BLOCK 2016-07-26T08:38:24.181Z org.iungo.dataset.bulkload.DXFDatasetBulkload#5 bulkload#11 Finally RETURN 2016-07-26T08:38:24.181Z org.iungo.dataset.bulkload.DXFDatasetBulkload#5 bulkload#11 Return Timer [Started [2016:07:26 09:37:28] Stopped [2016:07:26 09:38:24] Elapsed [56097ms]] Value [org.iungo.result.Result] VARIABLE 2016-07-26T08:38:24.182Z org.iungo.dataset.bulkload.DXFDatasetBulkload#5 bulkload#11 Return Value [false [java.lang.UnsupportedOperationException: java.lang.OutOfMemoryError: GC overhead limit exceeded org.iungo.logger.MethodLogger.call(MethodLogger.java:107) org.iungo.dataset.bulkload.DXFDatasetBulkload.bulkload(DXFDatasetBulkload.java:500) org.iungo.dataset.node.DatasetNode$1$1.accept(DatasetNode.java:222) org.iungo.dataset.node.DatasetNode$1$1.accept(DatasetNode.java:1) org.iungo.queue.Q.process(Q.java:64) org.iungo.queue.Q$1.run(Q.java:45) java.lang.Thread.run(Thread.java:745)Cause: java.lang.OutOfMemoryError: GC overhead limit exceeded java.nio.HeapByteBuffer.asIntBuffer(HeapByteBuffer.java:391) org.apache.jena.tdb.base.buffer.PtrBuffer.<init>(PtrBuffer.java:47) org.apache.jena.tdb.index.bplustree.BPTreeNodeMgr.formatBPTreeNode(BPTreeNodeMgr.java:259) org.apache.jena.tdb.index.bplustree.BPTreeNodeMgr.overlay(BPTreeNodeMgr.java:204) org.apache.jena.tdb.index.bplustree.BPTreeNodeMgr.access$000(BPTreeNodeMgr.java:36) org.apache.jena.tdb.index.bplustree.BPTreeNodeMgr$Block2BPTreeNode.fromBlock(BPTreeNodeMgr.java:144) org.apache.jena.tdb.index.bplustree.BPTreeNodeMgr$Block2BPTreeNode.fromBlock(BPTreeNodeMgr.java:119) org.apache.jena.tdb.base.page.PageBlockMgr.getRead(PageBlockMgr.java:68) org.apache.jena.tdb.index.bplustree.BPTreeNodeMgr.getRead(BPTreeNodeMgr.java:105) org.apache.jena.tdb.index.bplustree.BPTreeNodeMgr.getRoot(BPTreeNodeMgr.java:90) org.apache.jena.tdb.index.bplustree.BPlusTree.getRoot(BPlusTree.java:237) org.apache.jena.tdb.index.bplustree.BPlusTree.addAndReturnOld(BPlusTree.java:325) org.apache.jena.tdb.index.bplustree.BPlusTree.add(BPlusTree.java:318) org.apache.jena.tdb.store.tupletable.TupleIndexRecord.performAdd(TupleIndexRecord.java:60) org.apache.jena.tdb.store.tupletable.TupleIndexBase.add(TupleIndexBase.java:62) org.apache.jena.tdb.store.tupletable.TupleTable.add(TupleTable.java:95) org.apache.jena.tdb.store.nodetupletable.NodeTupleTableConcrete.addRow(NodeTupleTableConcrete.java:88) org.apache.jena.tdb.store.QuadTable.add(QuadTable.java:60) org.apache.jena.tdb.store.DatasetGraphTDB.addToNamedGraph(DatasetGraphTDB.java:98) org.apache.jena.sparql.core.DatasetGraphTriplesQuads.add(DatasetGraphTriplesQuads.java:49) org.apache.jena.sparql.core.DatasetGraphWrapper.add(DatasetGraphWrapper.java:106) org.iungo.dataset.bulkload.DXFDatasetBulkload$2.visit(DXFDatasetBulkload.java:340) org.iungo.dataset.bulkload.DXFDatasetBulkload$2.visit(DXFDatasetBulkload.java:355) org.kabeja.entities.Entity.accept(Entity.java:67) org.iungo.dataset.bulkload.DXFDatasetBulkload$2.visit(DXFDatasetBulkload.java:312) org.kabeja.common.Block.accept(Block.java:59) org.iungo.dataset.bulkload.DXFDatasetBulkload$2.visit(DXFDatasetBulkload.java:197) org.kabeja.DraftDocument.accept(DraftDocument.java:100) org.iungo.dataset.bulkload.DXFDatasetBulkload$6.get(DXFDatasetBulkload.java:503) org.iungo.dataset.bulkload.DXFDatasetBulkload$6.get(DXFDatasetBulkload.java:1) org.iungo.logger.MethodLogger.call(MethodLogger.java:104) org.iungo.dataset.bulkload.DXFDatasetBulkload.bulkload(DXFDatasetBulkload.java:500)] [java.lang.UnsupportedOperationException]]
