Performance decrease wrongly

[ypriverol]

Performance decrease wrongly

[tzaeschke]

I never noticed that before.
I just tested Test_050_ObjectCreation.testLargerOidIndex() with 10M Objects, that took 79 seconds.
Could you descibe a bit more what you are doing?

• Are you using other indexes?
• How often are you committing?

It us usually faster to create indexes after inserting all objects. Also, transactions should not be too small, at least 100-1000 objects per transactions, my test even puts everything into a single transaction.
Are you maybe running into memory/GC issues?
Could you maybe post an example program and a simple profile, made with -Xprof ?

[ypriverol]

Hi @tzaeschke, I did some benchmark using -Xprof, here the results:

Flat profile of 3747.92 secs (10115 total ticks): Attach Listener

  Interpreted + native   Method                        
  0.0%     0  +     1    java.io.FileInputStream.readBytes
  0.0%     0  +     1    Total interpreted

  Thread-local ticks:
  0.0%     1             Class loader
100.0% 10113             Unknown: no last frame


Flat profile of 3748.74 secs (10166 total ticks): main

  Interpreted + native   Method                        
  8.4%     0  +   851    sun.nio.ch.FileDispatcherImpl.force0
  0.1%    15  +     0    org.bigbio.pgatk.io.properties.PropertyStorageTest.clusteringObjectDBTest
  0.1%    10  +     0    org.bigbio.pgatk.io.objectdb.ObjectsDB.insertObjects
  0.1%     0  +     9    java.lang.Runtime.gc
  0.1%     9  +     0    org.bigbio.pgatk.io.objectdb.ObjectsCache.saveObjects
  0.1%     6  +     1    java.lang.ClassLoader.defineClass1
  0.1%     6  +     0    java.util.HashMap.putMapEntries
  0.1%     0  +     6    java.util.zip.ZipFile.open
  0.0%     3  +     0    java.util.LinkedList.addAll
  0.0%     1  +     2    sun.nio.ch.NativeThread.current
  0.0%     0  +     2    java.io.UnixFileSystem.getLastModifiedTime
  0.0%     2  +     0    java.io.OutputStreamWriter.write
  0.0%     2  +     0    java.util.zip.ZipFile.getInputStream
  0.0%     1  +     1    java.lang.Class.forName0
  0.0%     2  +     0    java.util.HashMap.resize
  0.0%     2  +     0    java.util.HashMap.clear
  0.0%     2  +     0    sun.misc.URLClassPath$JarLoader.checkResource
  0.0%     0  +     2    java.util.zip.Inflater.inflateBytes
  0.0%     1  +     1    java.util.zip.ZipFile.getEntryCSize
  0.0%     2  +     0    org.zoodb.internal.ObjectGraphTraverser.traverseCache
  0.0%     1  +     1    java.lang.System.nanoTime
  0.0%     2  +     0    org.zoodb.internal.util.PrimLongMapZSoft.putIfAbsent
  0.0%     2  +     0    java.util.jar.JarFile.maybeInstantiateVerifier
  0.0%     2  +     0    org.zoodb.internal.server.index.LLIndexPage.addSubPage
  0.0%     2  +     0    java.util.AbstractCollection.toArray
 10.5%   175  +   897    Total interpreted (including elided)

     Compiled + native   Method                        
 13.4%  1361  +     2    org.zoodb.jdo.impl.PersistenceManagerImpl.makePersistent
  6.2%   623  +     8    org.bigbio.pgatk.io.properties.PropertyStorageTest.clusteringObjectDBTest
  3.0%   310  +     0    org.zoodb.internal.client.PCContext.notifyEvent
  3.0%   305  +     1    java.util.HashMap.putMapEntries
  2.9%   297  +     0    org.zoodb.internal.DataSerializer.serializeFields1
  2.2%   227  +     0    org.zoodb.internal.ObjectGraphTraverser.traverseCache
  2.2%   223  +     0    org.zoodb.internal.DataSerializer.serializeObject
  2.0%   199  +     4    org.bigbio.pgatk.io.objectdb.ObjectsCache.saveObjects
  1.9%   192  +     1    org.bigbio.pgatk.io.objectdb.ObjectsDB.insertObjects
  1.8%   169  +     9    java.util.HashMap.resize
  1.1%   112  +     0    org.zoodb.internal.server.index.LLIndexPage.locatePageForKey
  1.0%    96  +     4    org.zoodb.internal.Session.getObjectToCommit
  0.9%    87  +     0    org.zoodb.internal.server.index.LLIndexPage.put
  0.8%    82  +     1    org.zoodb.internal.model1p.DataSink1P.write
  0.4%    45  +     0    org.zoodb.internal.server.ObjectWriterSV.startObject
  0.4%    37  +     3    java.util.LinkedList.addAll
  0.2%    16  +     2    org.zoodb.internal.client.session.ClientSessionCache.postCommit
  0.1%    14  +     0    org.bigbio.pgatk.io.objectdb.ObjectsCache.addObjects
  0.1%    10  +     1    org.zoodb.internal.server.StorageChannelImpl.getNextPage
  0.1%    10  +     0    sun.misc.FloatingDecimal$BinaryToASCIIBuffer.dtoa
  0.1%    10  +     0    java.util.HashMap.putVal
  0.1%     9  +     0    org.zoodb.internal.Session.commitInternal
  0.1%     8  +     0    java.util.HashMap.get
  0.1%     3  +     3    org.zoodb.internal.server.index.AbstractIndexPage.write
  0.0%     4  +     0    java.util.HashMap.put
 45.0%  4517  +    58    Total compiled (including elided)

         Stub + native   Method                        
 24.8%     0  +  2526    sun.nio.ch.FileDispatcherImpl.pwrite0
  7.4%     0  +   750    java.lang.Class.getEnclosingMethod0
  7.3%     0  +   742    sun.nio.ch.NativeThread.current
  1.3%     0  +   128    sun.nio.ch.FileDispatcherImpl.force0
  0.9%     0  +    87    java.lang.Class.getDeclaringClass0
  0.7%     0  +    74    java.io.FileOutputStream.writeBytes
  0.4%     0  +    36    java.lang.Throwable.getStackTraceElement
  0.2%     0  +    24    java.lang.Throwable.fillInStackTrace
  0.2%     0  +    23    java.lang.Thread.isInterrupted
  0.2%     0  +    20    java.nio.Bits.copyFromLongArray
  0.2%     0  +    19    java.lang.Object.getClass
  0.1%     0  +    14    java.util.zip.ZipFile.getEntry
  0.1%     0  +    10    java.lang.Class.isAssignableFrom
  0.1%     0  +     7    java.lang.Class.isArray
  0.1%     0  +     7    java.util.zip.ZipFile.read
  0.1%     0  +     7    java.util.zip.Inflater.inflateBytes
  0.1%     0  +     6    java.io.UnixFileSystem.getBooleanAttributes0
  0.0%     0  +     4    java.lang.Runtime.gc
  0.0%     0  +     3    sun.misc.Unsafe.copyMemory
  0.0%     0  +     3    java.lang.Object.hashCode
  0.0%     0  +     3    java.lang.System.arraycopy
  0.0%     0  +     3    java.lang.Thread.currentThread
  0.0%     3  +     0    java.lang.ClassLoader.defineClass1
  0.0%     0  +     3    java.nio.Bits.copyFromIntArray
  0.0%     0  +     3    java.lang.Runtime.totalMemory
 44.4%     3  +  4510    Total stub (including elided)

  Thread-local ticks:
  0.1%     6             Class loader

 Bytecode ticks:
     5    0 = ldc
     2    0 = goto
     1    1 = getstatic
     2    0 = putstatic
     9    0 = invokevirtual
     2    0 = invokespecial
     5    1 = invokestatic
     8    0 = new
     4    0 = newarray
     5    0 = anewarray
     2    0 = fast_aldc


Global summary of 3748.74 seconds:
100.0% 309384            Received ticks
 96.7% 299210            Received GC ticks
  0.2%   690             Compilation
  0.0%     8             Other VM operations
  0.0%     7             Class loader
  3.3% 10113             Unknown code


Flat profile of 0.00 secs (309083 total ticks): VM Thread
  0.1%   301             Lost ticks

     Compiled + native   Method                        
 98.6%     0  + 304764   __psynch_cvwait
  0.4%     0  +  1178    ObjArrayKlass::oop_update_pointers(ParCompactionManager*, oopDesc*)
  0.3%     0  +  1059    ParallelCompactData::calc_new_pointer(HeapWord*)
  0.3%     0  +  1054    ParMarkBitMap::live_words_in_range(HeapWord*, oopDesc*) const
  0.1%     0  +   390    BitMap::clear_range(unsigned long, unsigned long)
  0.1%     0  +   155    java_lang_ref_Reference::discovered(oopDesc*)
  0.0%     0  +    65    CardTableModRefBS::dirty_MemRegion(MemRegion)
  0.0%     0  +    62    PSParallelCompact::IsAliveClosure::do_object_b(oopDesc*)
  0.0%     0  +    56    SymbolTable::buckets_unlink(int, int, int*, int*, unsigned long*)
  0.0%     0  +    48    _platform_bzero$VARIANT$Haswell
  0.0%     0  +    33    RelocIterator::next()
  0.0%     0  +    21    InstanceKlass::clean_method_data(BoolObjectClosure*)
  0.0%     0  +    18    void PSParallelCompact::mark_and_push<unsigned int>(ParCompactionManager*, unsigned int*)
  0.0%     0  +    11    __psynch_mutexwait
  0.0%     0  +    11    CodeHeap::next_free(HeapBlock*) const
  0.0%     0  +     9    DataLayout::data_in()
  0.0%     0  +     9    PSParallelCompact::update_deferred_objects(ParCompactionManager*, PSParallelCompact::SpaceId)
  0.0%     0  +     8    InstanceKlass::oop_update_pointers(ParCompactionManager*, oopDesc*)
  0.0%     0  +     7    java_lang_ref_Reference::referent(oopDesc*)
  0.0%     0  +     7    __psynch_cvsignal
  0.0%     0  +     7    StringTable::buckets_unlink_or_oops_do(BoolObjectClosure*, OopClosure*, int, int, int*, int*)
  0.0%     0  +     6    nmethod::fix_oop_relocations(unsigned char*, unsigned char*, bool)
  0.0%     0  +     5    __mprotect
  0.0%     0  +     5    PSParallelCompact::AdjustPointerClosure::do_oop(oopDesc**)
  0.0%     0  +     5    MethodData::clean_method_data(BoolObjectClosure*)
100.0%     0  + 309083   Total compiled (including elided)

[tzaeschke]

If I read this right then the process is 96.7% busy with garbage collection. Maybe you could allocate more memory with -Xmx ?
Also, what about the other questions (commit interval & indexing)?

Regarding GC, normally ZooDB should allow garbage collection of objects that have already been written to disk, but to be sure, you could close/reopen the PersistenceManager every 100000 objects or so. This should not be necessary, but let me know if it makes a difference.

[tzaeschke]

Does the problem still persist?

[tzaeschke]

Please reopen if problem occurs again