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]]