Re: Jena TDB OOME GC overhead limit exceeded

[Dick Murray]

Hello.

Something doesn't add up here... I've run repeated tests with the following
MWE on a 16GB machine with -Xms8g -Xmx8g and the I always get an OOME.

What I don't understand is the size of [B increases with each pass until
the OOME is thrown. The exact same process is run 5 times with a new graph
for each set of triples.

There are ~3.5M triples added within the transaction from a file which is a
"simple" text based file (30Mb) which is read in line pairs.

I've tested sequential loads of other text files (i.e. file x *5) and other
text files loaded sequentally (i.e. file x, file y, file ...) and the same
result is exhibited.

If I reduce -Xmx to 6g it will fail earlier.

Changing the GC using -XX:+UseGC1C doesn't alter the outcome.

I'm running on Ubuntu 16.04 with Java 1.8 and I can replicate this on
Centos 7 with Java 1.8.

Any ideas?

Regards Dick.


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:~$


Complete code example below which shows this error, followed by output of
said program. This will attempt to exec jps and jmap...

package org.iungo.dxf;

import java.io.BufferedReader;
import java.io.InputStreamReader;
import java.net.URL;
import java.nio.charset.StandardCharsets;
import java.time.Instant;
import java.util.LinkedList;
import java.util.List;
import java.util.Objects;
import java.util.UUID;

import org.apache.jena.graph.Node;
import org.apache.jena.graph.NodeFactory;
import org.apache.jena.query.ReadWrite;
import org.apache.jena.sparql.core.DatasetGraph;
import org.apache.jena.tdb.TDBFactory;

public class DXFStream {
static String pid = pid();
public static void main(final String[] args) {

Objects.requireNonNull(pid);
final String dg =
"/home/dick/eclipse-jee-neon/git/iungo-core/iungo-core/tdb-dataset-node";
final String dxf =
"file:///home/dick/eclipse-jee-neon/git/iungo-ssl/iungo-ssl/test/resources/0005_XXXX-SSL-XXX-XX-DR-U-0200.dxf";
try {
mem();
log("open");
final DatasetGraph datasetGraph = TDBFactory.createDatasetGraph(dg);
for (int i = 1; i <= 5; i++) {
log("Pass " + String.valueOf(i));
try {
mem();
log("begin WRITE");
datasetGraph.begin(ReadWrite.WRITE);
Node g = NodeFactory.createURI(UUID.randomUUID().toString());
Node pk = NodeFactory.createURI("k");
Node pv = NodeFactory.createURI("v");
final BufferedReader bufferedReader = new BufferedReader(new
InputStreamReader(new URL(dxf).openStream(), StandardCharsets.UTF_8));
String key = null;
String value = null;
Integer count = 0;
while ((key = bufferedReader.readLine()) != null) {
key = key.trim();
if ((value = bufferedReader.readLine()) == null) {
throw new UnsupportedOperationException();
}
count++;
datasetGraph.add(g, NodeFactory.createURI(count.toString()), pk,
NodeFactory.createLiteral(key));
datasetGraph.add(g, NodeFactory.createURI(count.toString()), pv,
NodeFactory.createLiteral(value));
}
bufferedReader.close();
mem();
log(count * 2 + " commit");
datasetGraph.commit();
} catch (final Throwable throwable) {
System.err.println(throwable);
mem();
log("abort");
datasetGraph.abort();
} finally {
mem();
log("end");
datasetGraph.end();
}
}
mem();
log("close");
datasetGraph.close();
} catch (final Throwable throwable) {
System.err.println(throwable);
}
log("exit");
}
public static String pid() {
log("pid");
try {
String pid = null;
final Process p = Runtime.getRuntime().exec(new String[]{"jps", "-m"});
final BufferedReader pbr = new BufferedReader(new
InputStreamReader(p.getInputStream()));
String line = null;
while ((line = pbr.readLine()) != null) {
final String name = line.substring(line.indexOf(" ")).trim();
if (name.equals("DXFStream")) {
pid = line.substring(0, line.indexOf(" "));
log(line);
break;
}
}
p.waitFor();
pbr.close();
log(pid);
return pid;
} catch (final Throwable throwable) {
System.err.println(throwable);
return null;
}
}
public static void jmap() {
log("jmap");
try {
// JVM doesn't like | so use a list then stream and limit to 13...
final Process p = Runtime.getRuntime().exec(new String[]{"jmap", "-histo",
pid});
List<String> lines = new LinkedList<>();
String line = null;
final BufferedReader pbr = new BufferedReader(new
InputStreamReader(p.getInputStream()));
while ((line = pbr.readLine()) != null) {
lines.add(line);
}
p.waitFor();
pbr.close();
lines
.stream()
.limit(13)
.forEach(text -> System.out.println(text));
} catch (final Throwable throwable) {
System.err.println(throwable);
}
}
public static void mem() {
log(Runtime.getRuntime().freeMemory() + " " +
Runtime.getRuntime().totalMemory() + " " +
Runtime.getRuntime().maxMemory());
jmap();
}
public static void log(final String text) {
System.out.println(Instant.now() + " " + text);
}
}


Output;

2016-07-27T09:47:28.013Z pid
2016-07-27T09:47:28.265Z 24777 DXFStream
2016-07-27T09:47:28.279Z 24777
2016-07-27T09:47:28.279Z 8581545984 8589934592 8589934592
2016-07-27T09:47:28.279Z jmap

 num     #instances         #bytes  class name
----------------------------------------------
   1:          1660        5882344  [I
   2:          8870         781312  [C
   3:          1877         518512  [B
   4:          3305         185080  jdk.internal.org.objectweb.asm.Item
   5:          5968         143232  java.lang.String
   6:           183         108720  [Ljdk.internal.org.objectweb.asm.Item;
   7:           869          98912  java.lang.Class
   8:          1533          73376  [Ljava.lang.Object;
   9:          1531          46056  [Ljava.lang.Class;
  10:           975          39000  java.lang.invoke.MethodType
2016-07-27T09:47:28.608Z open
log4j:WARN No appenders could be found for logger (Jena).
log4j:WARN Please initialize the log4j system properly.
log4j:WARN See http://logging.apache.org/log4j/1.2/faq.html#noconfig for
more info.
2016-07-27T09:47:29.545Z Pass 1
2016-07-27T09:47:29.545Z 8485076992 8589934592 8589934592
2016-07-27T09:47:29.545Z jmap

 num     #instances         #bytes  class name
----------------------------------------------
   1:        242513       44518552  [B
   2:        299163       44378872  [C
   3:          6296        6640984  [I
   4:         92122        2210928  java.lang.String
   5:         18253        1168192  java.net.URL
   6:          3030         810032  [Z
   7:          6947         619192  [Ljava.lang.Object;
   8:         18739         449736  java.lang.StringBuilder
   9:          2800         315920  java.lang.Class
  10:          8984         287488  java.io.File
2016-07-27T09:47:29.702Z begin WRITE
2016-07-27T09:48:14.349Z 6515849168 8589934592 8589934592
2016-07-27T09:48:14.349Z jmap

 num     #instances         #bytes  class name
----------------------------------------------
   1:       4557903     1495719048  [B
   2:          6517      172190960  [I
   3:       2196732       70295424  java.util.HashMap$Node
   4:       4056802       64908832
 org.apache.jena.tdb.index.IndexMap$ByteArray
   5:       1142702       54849696  java.nio.HeapByteBuffer
   6:           323       35608424  [Ljava.util.HashMap$Node;
   7:        229268       24811416  [C
   8:        394546       22094576  java.nio.ByteBufferAsIntBufferB
   9:        410538       19705824
 org.apache.jena.tdb.index.bplustree.BPTreeNode
  10:        598134       19140288
 org.apache.jena.tdb.base.buffer.RecordBuffer
2016-07-27T09:48:14.908Z 3584944 commit
2016-07-27T09:48:46.779Z 2835346896 8589934592 8589934592
2016-07-27T09:48:46.779Z jmap

 num     #instances         #bytes  class name
----------------------------------------------
   1:       6361124     1554294080  [B
   2:      25799331     1241839712  [C
   3:       6825270      436817280  java.nio.DirectByteBuffer
   4:       2760425      373528376  [I
   5:      13732445      329578680  java.lang.String
   6:       2560322      107850096  [Ljava.lang.Object;
   7:       3152201      100870432  org.apache.jena.tdb.base.block.Block
   8:       1705332       95498592  java.nio.DirectIntBufferS
   9:       1778664       85375872
 org.apache.jena.ext.com.google.common.cache.LocalCache$StrongAccessEntry
  10:       1317667       84330688  java.util.regex.Matcher
2016-07-27T09:48:49.944Z end
2016-07-27T09:48:49.944Z Pass 2
2016-07-27T09:48:49.944Z 2833251784 8589934592 8589934592
2016-07-27T09:48:49.944Z jmap

 num     #instances         #bytes  class name
----------------------------------------------
   1:       6361136     1554327144  [B
   2:      25801499     1242271736  [C
   3:       6825270      436817280  java.nio.DirectByteBuffer
   4:       2760428      375049432  [I
   5:      13733625      329607000  java.lang.String
   6:       2560323      107850128  [Ljava.lang.Object;
   7:       3152201      100870432  org.apache.jena.tdb.base.block.Block
   8:       1705332       95498592  java.nio.DirectIntBufferS
   9:       1778664       85375872
 org.apache.jena.ext.com.google.common.cache.LocalCache$StrongAccessEntry
  10:       1317667       84330688  java.util.regex.Matcher
2016-07-27T09:48:53.105Z begin WRITE
2016-07-27T09:49:59.545Z 3980392408 8589934592 8589934592
2016-07-27T09:49:59.545Z jmap

 num     #instances         #bytes  class name
----------------------------------------------
   1:       6326761     2979960992  [B
   2:         10713      262297504  [I
   3:       4135536      198505728  java.nio.HeapByteBuffer
   4:       2490408      119539584
 org.apache.jena.ext.com.google.common.cache.LocalCache$StrongAccessEntry
   5:       2977703      119226888  [C
   6:       1624056       90947136  java.nio.ByteBufferAsIntBufferB
   7:       1729819       83031312
 org.apache.jena.tdb.index.bplustree.BPTreeNode
   8:       2443706       78198592  java.util.HashMap$Node
   9:       2330432       74573824
 org.apache.jena.tdb.base.buffer.RecordBuffer
  10:       4037260       64596160
 org.apache.jena.tdb.index.IndexMap$ByteArray
2016-07-27T09:50:00.837Z 3584944 commit
2016-07-27T09:50:04.687Z 3978297296 8589934592 8589934592
2016-07-27T09:50:04.687Z jmap

 num     #instances         #bytes  class name
----------------------------------------------
   1:       6326778     2979994376  [B
   2:         10726      263755440  [I
   3:       4135539      198505872  java.nio.HeapByteBuffer
   4:       2979948      119662608  [C
   5:       2490411      119539728
 org.apache.jena.ext.com.google.common.cache.LocalCache$StrongAccessEntry
   6:       1624056       90947136  java.nio.ByteBufferAsIntBufferB
   7:       1729823       83031504
 org.apache.jena.tdb.index.bplustree.BPTreeNode
   8:       2443706       78198592  java.util.HashMap$Node
   9:       2330438       74574016
 org.apache.jena.tdb.base.buffer.RecordBuffer
  10:       4037260       64596160
 org.apache.jena.tdb.index.IndexMap$ByteArray
2016-07-27T09:50:05.985Z end
2016-07-27T09:50:05.985Z Pass 3
2016-07-27T09:50:05.985Z 3978297296 8589934592 8589934592
2016-07-27T09:50:05.985Z jmap

 num     #instances         #bytes  class name
----------------------------------------------
   1:       6326790     2980027440  [B
   2:         10728      263190264  [I
   3:       4135540      198505920  java.nio.HeapByteBuffer
   4:       2982087      120086088  [C
   5:       2490411      119539728
 org.apache.jena.ext.com.google.common.cache.LocalCache$StrongAccessEntry
   6:       1624056       90947136  java.nio.ByteBufferAsIntBufferB
   7:       1729823       83031504
 org.apache.jena.tdb.index.bplustree.BPTreeNode
   8:       2443706       78198592  java.util.HashMap$Node
   9:       2330438       74574016
 org.apache.jena.tdb.base.buffer.RecordBuffer
  10:       4037260       64596160
 org.apache.jena.tdb.index.IndexMap$ByteArray
2016-07-27T09:50:07.290Z begin WRITE
2016-07-27T09:51:14.739Z 1262220808 8589934592 8589934592
2016-07-27T09:51:14.739Z jmap

 num     #instances         #bytes  class name
----------------------------------------------
   1:       4430710     5026141640  [B
   2:       8029842      385432416  java.nio.HeapByteBuffer
   3:       3180387      178101672  java.nio.ByteBufferAsIntBufferB
   4:       3391387      162786576
 org.apache.jena.tdb.index.bplustree.BPTreeNode
   5:       4571970      146303040
 org.apache.jena.tdb.base.buffer.RecordBuffer
   6:       3391399      108524768
 org.apache.jena.tdb.base.buffer.PtrBuffer
   7:       2206321       99763816  [C
   8:       3753206       90076944  java.lang.Long
   9:        852205       54541120  java.nio.DirectByteBuffer
  10:       1095522       52585056
 org.apache.jena.ext.com.google.common.cache.LocalCache$StrongAccessEntry
2016-07-27T09:51:16.184Z 3584944 commit
2016-07-27T09:51:22.278Z 1260125696 8589934592 8589934592
2016-07-27T09:51:22.278Z jmap

 num     #instances         #bytes  class name
----------------------------------------------
   1:       4430727     5026175024  [B
   2:       8029845      385432560  java.nio.HeapByteBuffer
   3:       3180387      178101672  java.nio.ByteBufferAsIntBufferB
   4:       3391391      162786768
 org.apache.jena.tdb.index.bplustree.BPTreeNode
   5:       4571976      146303232
 org.apache.jena.tdb.base.buffer.RecordBuffer
   6:       3391403      108524896
 org.apache.jena.tdb.base.buffer.PtrBuffer
   7:       2208549      100194736  [C
   8:       3753216       90077184  java.lang.Long
   9:        852221       54542144  java.nio.DirectByteBuffer
  10:       1095525       52585200
 org.apache.jena.ext.com.google.common.cache.LocalCache$StrongAccessEntry
2016-07-27T09:51:23.923Z end
2016-07-27T09:51:23.923Z Pass 4
2016-07-27T09:51:23.924Z 1258026504 8589934592 8589934592
2016-07-27T09:51:23.924Z jmap

 num     #instances         #bytes  class name
----------------------------------------------
   1:       4430739     5026208088  [B
   2:       8029846      385432608  java.nio.HeapByteBuffer
   3:       3180387      178101672  java.nio.ByteBufferAsIntBufferB
   4:       3391391      162786768
 org.apache.jena.tdb.index.bplustree.BPTreeNode
   5:       4571976      146303232
 org.apache.jena.tdb.base.buffer.RecordBuffer
   6:       3391403      108524896
 org.apache.jena.tdb.base.buffer.PtrBuffer
   7:       2210716      100626880  [C
   8:       3753224       90077376  java.lang.Long
   9:        852221       54542144  java.nio.DirectByteBuffer
  10:       1095525       52585200
 org.apache.jena.ext.com.google.common.cache.LocalCache$StrongAccessEntry
2016-07-27T09:51:25.275Z begin WRITE
2016-07-27T09:52:39.925Z 314305368 8589934592 8589934592
2016-07-27T09:52:39.925Z jmap

 num     #instances         #bytes  class name
----------------------------------------------
   1:       1319938     7682030072  [B
   2:       1702288       81709824  java.nio.HeapByteBuffer
   3:       1281483       41007456  java.util.HashMap$Node
   4:        770721       36994608
 org.apache.jena.ext.com.google.common.cache.LocalCache$StrongAccessEntry
   5:        962343       30794976  org.apache.jena.tdb.base.block.Block
   6:        737804       28430888  [C
   7:           310       27899112  [Ljava.util.HashMap$Node;
   8:          1834       27200896  [I
   9:        935394       22449456  java.lang.Long
  10:        328196       18378976  java.nio.ByteBufferAsIntBufferB
2016-07-27T09:52:40.574Z 3584944 commit
2016-07-27T09:52:47.761Z 312210256 8589934592 8589934592
2016-07-27T09:52:47.761Z jmap

 num     #instances         #bytes  class name
----------------------------------------------
   1:       1319955     7682063456  [B
   2:       1702291       81709968  java.nio.HeapByteBuffer
   3:       1281483       41007456  java.util.HashMap$Node
   4:        770723       36994704
 org.apache.jena.ext.com.google.common.cache.LocalCache$StrongAccessEntry
   5:        962350       30795200  org.apache.jena.tdb.base.block.Block
   6:        739988       28854128  [C
   7:          1847       28725888  [I
   8:           310       27899112  [Ljava.util.HashMap$Node;
   9:        935404       22449696  java.lang.Long
  10:        328196       18378976  java.nio.ByteBufferAsIntBufferB
2016-07-27T09:52:48.404Z end
2016-07-27T09:52:48.404Z Pass 5
2016-07-27T09:52:48.404Z 312210256 8589934592 8589934592
2016-07-27T09:52:48.404Z jmap

 num     #instances         #bytes  class name
----------------------------------------------
   1:       1319967     7682096520  [B
   2:       1702292       81710016  java.nio.HeapByteBuffer
   3:       1281483       41007456  java.util.HashMap$Node
   4:        770723       36994704
 org.apache.jena.ext.com.google.common.cache.LocalCache$StrongAccessEntry
   5:        962350       30795200  org.apache.jena.tdb.base.block.Block
   6:        742126       29280704  [C
   7:          1849       28158216  [I
   8:           310       27899112  [Ljava.util.HashMap$Node;
   9:        935412       22449888  java.lang.Long
  10:        328196       18378976  java.nio.ByteBufferAsIntBufferB
2016-07-27T09:52:49.082Z begin WRITE

Exception: java.lang.OutOfMemoryError thrown from the
UncaughtExceptionHandler in thread "main"


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

> On 26/07/16 16:51, Dick Murray wrote:
>
>> Ok, I set that option and I get different OOME from the direct buffer
>> memory.
>>
>
> You now have:
>
> > java.lang.OutOfMemoryError:
> > Direct buffer memory
>
> So that means the direct memory space has run out, not the heap.
>
> You can increase direct memory but that isn't getting to the root cause.
>
> 200k quads isn't that many, though the JVM arg "-Xmx4g" is pretty small
> for largish transactions.  But you are doing it 5 times.  I calculated
> maybe 300M-1G of temp space but the calculation is a bit "it depends". But
> that is 25% of the heap allocated already.
>
> Try to switch off the commit amalgamation.  Commits get aggregated so many
> one triple insert transactions don't cause vast overheads.
>
> TransactionManager.QueueBatchSize=0 ;
>
> In addition, the unusual size (for TDB) of many byte[] and other objects
> suggests that the non Jena code is using a significant slice of space as
> well.
>
> (without setting TDB.transactionJournalWriteBlockMode).
>
> Not setting TDB.transactionJournalWriteBlockMode is better but an
> alternative is "mapped" mode instead of "direct".
>
>         Andy
>
>
>> I then changed the GC using -XX:+UseG1GC (which still throws the OOME) and
>> I don't get why it's throwing the OOME.!?
>>
>>  [Eden: 2372.0M(2372.0M)->0.0B(1036.0M) Survivors: 84.0M->196.0M Heap:
>> 2979.4M(4096.0M)->720.4M(4096.0M)]
>>
>> Unless I'm mistaken I don't have a G1 Heap problem?
>>
>>
>> ...
>> [GC pause (G1 Evacuation Pause) (young), 0.1580047 secs]
>>    [Parallel Time: 149.8 ms, GC Workers: 8]
>>       [GC Worker Start (ms): Min: 463499.3, Avg: 463499.4, Max: 463499.5,
>> Diff: 0.1]
>>       [Ext Root Scanning (ms): Min: 0.2, Avg: 0.2, Max: 0.3, Diff: 0.2,
>> Sum: 1.8]
>>       [Update RS (ms): Min: 12.5, Avg: 12.6, Max: 12.7, Diff: 0.2, Sum:
>> 100.9]
>>          [Processed Buffers: Min: 13, Avg: 15.6, Max: 18, Diff: 5, Sum:
>> 125]
>>       [Scan RS (ms): Min: 18.7, Avg: 18.8, Max: 18.8, Diff: 0.2, Sum:
>> 150.2]
>>       [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0,
>> Sum: 0.1]
>>       [Object Copy (ms): Min: 116.7, Avg: 116.7, Max: 116.8, Diff: 0.1,
>> Sum: 933.8]
>>       [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum:
>> 0.0]
>>          [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
>>       [GC Worker Other (ms): Min: 0.0, Avg: 1.2, Max: 1.4, Diff: 1.3, Sum:
>> 9.3]
>>       [GC Worker Total (ms): Min: 148.3, Avg: 149.5, Max: 149.8, Diff:
>> 1.4,
>> Sum: 1196.1]
>>       [GC Worker End (ms): Min: 463647.8, Avg: 463648.9, Max: 463649.1,
>> Diff: 1.3]
>>    [Code Root Fixup: 0.0 ms]
>>    [Code Root Purge: 0.0 ms]
>>    [Clear CT: 0.8 ms]
>>    [Other: 7.3 ms]
>>       [Choose CSet: 0.0 ms]
>>       [Ref Proc: 4.7 ms]
>>       [Ref Enq: 0.0 ms]
>>       [Redirty Cards: 0.4 ms]
>>       [Humongous Register: 0.1 ms]
>>       [Humongous Reclaim: 0.0 ms]
>>       [Free CSet: 1.8 ms]
>>    [Eden: 2372.0M(2372.0M)->0.0B(1036.0M) Survivors: 84.0M->196.0M Heap:
>> 2979.4M(4096.0M)->720.4M(4096.0M)]
>>  [Times: user=1.13 sys=0.01, real=0.16 secs]
>> WARN 2016-07-26T15:26:10.196Z 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 16:26:05] Stopped
>> [2016:07:26 16:26:05] Elapsed [0ms]]]
>> [Full GC (System.gc())  849M->327M(4096M), 1.4194434 secs]
>>    [Eden: 130.0M(1036.0M)->0.0B(2456.0M) Survivors: 196.0M->0.0B Heap:
>> 849.4M(4096.0M)->327.7M(4096.0M)], [Metaspace: 18671K->18671K(1067008K)]
>>  [Times: user=1.80 sys=0.13, real=1.42 secs]
>> WARN 2016-07-26T15:26:12.001Z 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 16:24:03] Stopped
>> [2016:07:26 16:25:08] Elapsed [64979ms]]]
>> WARN 2016-07-26T15:26:12.002Z 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 16:21:45] Stopped
>> [2016:07:26 16:22:47] Elapsed [62554ms]]]
>> CALL_CATCH 2016-07-26T15:26:12.516Z
>> org.iungo.dataset.bulkload.DXFDatasetBulkload#3 bulkload#7
>> java.lang.OutOfMemoryError:
>> Direct buffer memory
>> java.nio.Bits.reserveMemory(Bits.java:693)
>> java.nio.DirectByteBuffer.<init>(DirectByteBuffer.java:123)
>> java.nio.ByteBuffer.allocateDirect(ByteBuffer.java:311)
>>
>> org.apache.jena.tdb.base.file.BufferAllocatorDirect.allocate(BufferAllocatorDirect.java:31)
>>
>> org.apache.jena.tdb.transaction.BlockMgrJournal.replicate(BlockMgrJournal.java:381)
>>
>> org.apache.jena.tdb.transaction.BlockMgrJournal.allocate(BlockMgrJournal.java:149)
>> org.apache.jena.tdb.base.page.PageBlockMgr.create(PageBlockMgr.java:51)
>>
>> org.apache.jena.tdb.index.bplustree.BPTreeRecordsMgr.create(BPTreeRecordsMgr.java:79)
>>
>> org.apache.jena.tdb.index.bplustree.BPTreeRecords.create(BPTreeRecords.java:207)
>>
>> org.apache.jena.tdb.index.bplustree.BPTreeRecords.split(BPTreeRecords.java:181)
>> org.apache.jena.tdb.index.bplustree.BPTreeNode.split(BPTreeNode.java:518)
>>
>> org.apache.jena.tdb.index.bplustree.BPTreeNode.internalInsert(BPTreeNode.java:454)
>>
>> org.apache.jena.tdb.index.bplustree.BPTreeNode.internalInsert(BPTreeNode.java:467)
>>
>> org.apache.jena.tdb.index.bplustree.BPTreeNode.internalInsert(BPTreeNode.java:467)
>> org.apache.jena.tdb.index.bplustree.BPTreeNode.insert(BPTreeNode.java:211)
>>
>> org.apache.jena.tdb.index.bplustree.BPlusTree.addAndReturnOld(BPlusTree.java:326)
>> 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:336)
>>
>> org.iungo.dataset.bulkload.DXFDatasetBulkload$2.visit(DXFDatasetBulkload.java:356)
>>
>> org.iungo.dataset.bulkload.DXFDatasetBulkload$2.visit(DXFDatasetBulkload.java:436)
>>
>> org.iungo.dataset.bulkload.DXFDatasetBulkload$2.visit(DXFDatasetBulkload.java:363)
>>
>> org.iungo.dataset.bulkload.DXFDatasetBulkload$2.visit(DXFDatasetBulkload.java:1)
>> org.kabeja.entities.Attrib.accept(Attrib.java:36)
>>
>> org.iungo.dataset.bulkload.DXFDatasetBulkload$2.visit(DXFDatasetBulkload.java:379)
>> org.kabeja.entities.Insert.accept(Insert.java:56)
>>
>> org.iungo.dataset.bulkload.DXFDatasetBulkload$2.visit(DXFDatasetBulkload.java:282)
>> org.kabeja.common.Layer.accept(Layer.java:61)
>>
>> org.iungo.dataset.bulkload.DXFDatasetBulkload$2.visit(DXFDatasetBulkload.java:193)
>> org.kabeja.DraftDocument.accept(DraftDocument.java:100)
>>
>> org.iungo.dataset.bulkload.DXFDatasetBulkload$6.get(DXFDatasetBulkload.java:504)
>>
>> 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:501)
>> 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)
>>
>>
>> Original GC
>>
>> [GC (System.gc()) [PSYoungGen: 912254K->27048K(1323520K)]
>> 1244937K->359739K(4120064K), 0.0178493 secs] [Times: user=0.12 sys=0.00,
>> real=0.01 secs]
>> [Full GC (System.gc()) [PSYoungGen: 27048K->0K(1323520K)] [ParOldGen:
>> 332690K->275014K(2796544K)] 359739K->275014K(4120064K), [Metaspace:
>> 18702K->18702K(1067008K)], 0.6541853 secs] [Times: user=4.11 sys=0.02,
>> real=0.66 secs]
>> [GC (Allocation Failure) [PSYoungGen: 1249792K->52800K(1315328K)]
>> 1524806K->327814K(4111872K), 0.0372440 secs] [Times: user=0.22 sys=0.00,
>> real=0.04 secs]
>> [GC (Allocation Failure) [PSYoungGen: 1297984K->10992K(1321472K)]
>> 1572998K->335623K(4118016K), 0.0398731 secs] [Times: user=0.24 sys=0.00,
>> real=0.04 secs]
>> [GC (System.gc()) [PSYoungGen: 230771K->2048K(1325056K)]
>> 555403K->336871K(4121600K), 0.0101041 secs] [Times: user=0.06 sys=0.00,
>> real=0.02 secs]
>> [Full GC (System.gc()) [PSYoungGen: 2048K->0K(1325056K)] [ParOldGen:
>> 334823K->332700K(2796544K)] 336871K->332700K(4121600K), [Metaspace:
>> 18706K->18706K(1067008K)], 0.6672732 secs] [Times: user=4.40 sys=0.01,
>> real=0.66 secs]
>> CALL_CATCH 2016-07-26T15:07:18.146Z
>> org.iungo.dataset.bulkload.DXFDatasetBulkload#6 bulkload#13
>> java.lang.OutOfMemoryError: Direct buffer memory
>> java.nio.Bits.reserveMemory(Bits.java:693)
>> java.nio.DirectByteBuffer.<init>(DirectByteBuffer.java:123)
>> java.nio.ByteBuffer.allocateDirect(ByteBuffer.java:311)
>>
>> org.apache.jena.tdb.base.file.BufferAllocatorDirect.allocate(BufferAllocatorDirect.java:31)
>>
>> org.apache.jena.tdb.transaction.BlockMgrJournal.replicate(BlockMgrJournal.java:381)
>>
>> org.apache.jena.tdb.transaction.BlockMgrJournal._promote(BlockMgrJournal.java:220)
>>
>> org.apache.jena.tdb.transaction.BlockMgrJournal.promote(BlockMgrJournal.java:214)
>> org.apache.jena.tdb.base.page.PageBlockMgr.promote(PageBlockMgr.java:109)
>>
>> org.apache.jena.tdb.index.bplustree.BPTreeRecords.promote(BPTreeRecords.java:118)
>>
>> org.apache.jena.tdb.index.bplustree.BPTreeRecords.internalInsert(BPTreeRecords.java:130)
>>
>> org.apache.jena.tdb.index.bplustree.BPTreeNode.internalInsert(BPTreeNode.java:467)
>>
>> org.apache.jena.tdb.index.bplustree.BPTreeNode.internalInsert(BPTreeNode.java:467)
>>
>> org.apache.jena.tdb.index.bplustree.BPTreeNode.internalInsert(BPTreeNode.java:467)
>> org.apache.jena.tdb.index.bplustree.BPTreeNode.insert(BPTreeNode.java:211)
>>
>> org.apache.jena.tdb.index.bplustree.BPlusTree.addAndReturnOld(BPlusTree.java:326)
>> 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:437)
>>
>> org.iungo.dataset.bulkload.DXFDatasetBulkload$2.visit(DXFDatasetBulkload.java:363)
>>
>> org.iungo.dataset.bulkload.DXFDatasetBulkload$2.visit(DXFDatasetBulkload.java:1)
>> org.kabeja.entities.Attrib.accept(Attrib.java:36)
>>
>> org.iungo.dataset.bulkload.DXFDatasetBulkload$2.visit(DXFDatasetBulkload.java:379)
>> org.kabeja.entities.Insert.accept(Insert.java:56)
>>
>> org.iungo.dataset.bulkload.DXFDatasetBulkload$2.visit(DXFDatasetBulkload.java:282)
>> org.kabeja.common.Layer.accept(Layer.java:61)
>>
>> org.iungo.dataset.bulkload.DXFDatasetBulkload$2.visit(DXFDatasetBulkload.java:193)
>> org.kabeja.DraftDocument.accept(DraftDocument.java:100)
>>
>> org.iungo.dataset.bulkload.DXFDatasetBulkload$6.get(DXFDatasetBulkload.java:504)
>>
>> 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:501)
>> 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)
>> Heap
>>  PSYoungGen      total 1325056K, used 139293K [0x000000076ab00000,
>> 0x00000007c0000000, 0x00000007c0000000)
>>   eden space 1251328K, 11% used
>> [0x000000076ab00000,0x0000000773307780,0x00000007b7100000)
>>   from space 73728K, 0% used
>> [0x00000007bb800000,0x00000007bb800000,0x00000007c0000000)
>>   to   space 72704K, 0% used
>> [0x00000007b7100000,0x00000007b7100000,0x00000007bb800000)
>>  ParOldGen       total 2796544K, used 332700K [0x00000006c0000000,
>> 0x000000076ab00000, 0x000000076ab00000)
>>   object space 2796544K, 11% used
>> [0x00000006c0000000,0x00000006d44e71a8,0x000000076ab00000)
>>  Metaspace       used 18734K, capacity 19032K, committed 19328K, reserved
>> 1067008K
>>   class space    used 2265K, capacity 2366K, committed 2432K, reserved
>> 1048576K
>>
>>
>> On 26 July 2016 at 14:40, Andy Seaborne <a...@apache.org> wrote:
>>
>> To build clean locally do the following:
>>>
>>> at the top level: not jena-tdb
>>>
>>> mvn clean install -Pbootstrap
>>> mvn install -Pdev
>>>
>>> (or "mvn clean install" but that builds and tests a lot more)
>>>
>>>         Andy
>>>
>>>
>>>
>>> On 26/07/16 14:25, Andy Seaborne wrote:
>>>
>>> On 26/07/16 14:11, Dick Murray wrote:
>>>>
>>>> Hi.
>>>>>
>>>>> I'll set that and run the process again.
>>>>>
>>>>> As an aside I just pulled Master and TDB won't compile because it's
>>>>> can't
>>>>> find MultiSet? Are there notes on getting the Jena GIT into Eclipse? I
>>>>> want
>>>>> to put a count on the BufferAllocatorMem to see what it's doing. I've
>>>>> put a
>>>>> break point on but gave up on F8 after counting to 500....
>>>>>
>>>>> Dick.
>>>>>
>>>>>
>>>> Make sure you have all the dependencies successfully resolved with
>>>>  mvn -o dependency:tree.
>>>>
>>>> The Apache snapshot repo was having a bad day earlier and Multiset is
>>>> from org.apache.jena:jena-shaded-guava:jar
>>>>
>>>>     Andy
>>>>
>>>>
>>>> On 26 July 2016 at 11:05, Andy Seaborne <a...@apache.org> wrote:
>>>>>
>>>>> 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
>>>>>>>>
>>>>>>>>