Re: Jena TDB OOME GC overhead limit exceeded

Tue, 26 Jul 2016 03:06:08 -0700 

On 26/07/16 10:51, Dick Murray wrote:

Hi.

Where do you set "transactionJournalWriteBlockMode" please?


We don't - its off by default.
It's a symbol you can set in the global context. TDB.transactionJournalWriteBlockMode
It is the only place that triggers DirectByteBuffers in TDB which I see in your jmap output. 



Would you expect to see a large number of [B heap entries in a 3.1 TDB?


Probably not, particularly not retained ones.

Looking at the average sizes:

>>>   1:        132187      636210296  [B
Average size: 4812.9
>>>   1:       1148534     1420727464  [B
Average size: 1237.0
>>>   1:       1377821     2328657400  [B
Average size: 1690.101544395099218258394958
>>>   1:        333123     2285460248  [B
Average size: 6860.7
>>>   1:        333123     2285460248  [B
Average size: 6860.7
>>>   1:        333123     2285460248  [B
Average size: 6860.7
>>>   1:        934984     3083070024  [B
Average size: 3297.5
>>>   1:       1067937     3321067472  [B
Average size: 3109.8
>>>   1:        581039     3615795256  [B
Average size: 6223.0

Does "6860.7" suggest anything?
It's not a unit in TDB that I recognize. Maybe the data has that in some way? 

        Andy



Dick.

On 26 July 2016 at 10:39, Andy Seaborne <a...@apache.org> wrote:


Dick,

The report is embedded in your application setup with a lot of
"org.iungo.dataset.bulkload"

Just because the OOME occurs in TDB does not mean that the space is
consumed in TDB - there may be a bigger memory hog elsewhere.

Could you produce an RDF example?

Maybe that file, already converted to RDF, and loaded with tdbloader?

If TDB is using DiretcByteBuffersm have you set
"transactionJournalWriteBlockMode" to "direct"?

You need to increase the direct memory space, not the heap.

        Andy


On 26/07/16 10:14, Dick Murray wrote:


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.j


...

[Message clipped]

Reply via email to