Application failure with traversal

Fri Feb 9 16:07:22 UTC 2018

I've today tried to run my company's product with shenandoah in traversal mode.

Regrettably, I get an NPE in an extremely unlikely place. Running with adaptive works well.

I'd like some advice on how I should collect some useful info for you. The test involves a multi-server setup, so I cannot easily provide any submittable testcase.

The application gets an NPE, so there is nothing special in the GC log. In fact, Shenandoah has not even logged a single GC event when this happens, but the statistics at the end of the log says "conc gc cancelled":

[19.363s][12329703955693228ns][19363105151ns][info ][gc               ] Cancelling concurrent GC: Stopping VM
[19.371s][12329703963748582ns][19371160173ns][info ][gc,heap,exit     ] Heap
[19.371s][12329703963756444ns][19371167983ns][info ][gc,heap,exit     ] Shenandoah Heap
[19.371s][12329703963763487ns][19371175018ns][info ][gc,heap,exit     ]  4915200K total, 2457600K committed, 1758038K used
[19.371s][12329703963769006ns][19371180537ns][info ][gc,heap,exit     ]  4800 x 1024K regions
[19.371s][12329703963774674ns][19371186203ns][info ][gc,heap,exit     ] Status: conc gc cancelled
[19.371s][12329703963779577ns][19371191098ns][info ][gc,heap,exit     ] Reserved region:
[19.371s][12329703963785276ns][19371196783ns][info ][gc,heap,exit     ]  - [0x0000000694000000, 0x00000007c0000000) 
[19.371s][12329703963797212ns][19371208735ns][info ][gc,stats         ] 
[19.371s][12329703963809671ns][19371221196ns][info ][gc,stats         ] GC STATISTICS:
[19.371s][12329703963818665ns][19371230203ns][info ][gc,stats         ]   "(G)" (gross) pauses include VM time: time to notify and block threads, do the pre-
[19.371s][12329703963824122ns][19371235623ns][info ][gc,stats         ]         and post-safepoint housekeeping. Use -XX:+PrintSafepointStatistics to dissect.
[19.371s][12329703963829094ns][19371240613ns][info ][gc,stats         ]   "(N)" (net) pauses are the times spent in the actual GC code.
[19.371s][12329703963833938ns][19371245470ns][info ][gc,stats         ]   "a" is average time for each phase, look at levels to see if average makes sense.
[19.371s][12329703963839340ns][19371250844ns][info ][gc,stats         ]   "lvls" are quantiles: 0% (minimum), 25%, 50% (median), 75%, 100% (maximum).
[19.371s][12329703963844056ns][19371255575ns][info ][gc,stats         ] 
[19.371s][12329703963852790ns][19371264319ns][info ][gc,stats         ] 
[19.371s][12329703963857376ns][19371268881ns][info ][gc,stats         ] 
[19.371s][12329703963862281ns][19371273784ns][info ][gc,stats         ] Under allocation pressure, concurrent cycles will cancel, and either continue cycle
[19.371s][12329703963867188ns][19371278702ns][info ][gc,stats         ] under stop-the-world pause or result in stop-the-world Full GC. Increase heap size,
[19.371s][12329703963873282ns][19371284825ns][info ][gc,stats         ] tune GC heuristics, or lower allocation rate to avoid degenerated and Full GC cycles.
[19.371s][12329703963878193ns][19371289703ns][info ][gc,stats         ] 
[19.371s][12329703963884440ns][19371295947ns][info ][gc,stats         ]     0 successful partial concurrent GCs
[19.371s][12329703963889124ns][19371300636ns][info ][gc,stats         ] 
[19.371s][12329703963893838ns][19371305360ns][info ][gc,stats         ]     0 successful concurrent GCs
[19.371s][12329703963899002ns][19371310518ns][info ][gc,stats         ]       0 invoked explicitly
[19.371s][12329703963903512ns][19371315042ns][info ][gc,stats         ] 
[19.371s][12329703963908148ns][19371319656ns][info ][gc,stats         ]     0 Degenerated GCs
[19.371s][12329703963913029ns][19371324542ns][info ][gc,stats         ]       0 caused by allocation failure
[19.371s][12329703963917988ns][19371329508ns][info ][gc,stats         ]       0 upgraded to Full GC
[19.371s][12329703963922565ns][19371334083ns][info ][gc,stats         ] 
[19.371s][12329703963927337ns][19371338844ns][info ][gc,stats         ]     0 Full GCs
[19.371s][12329703963932122ns][19371343636ns][info ][gc,stats         ]       0 invoked explicitly
[19.371s][12329703963936838ns][19371348352ns][info ][gc,stats         ]       0 caused by allocation failure
[19.371s][12329703963941726ns][19371353238ns][info ][gc,stats         ]       0 upgraded from Degenerated GC
[19.371s][12329703963946191ns][19371357729ns][info ][gc,stats         ] 
[19.371s][12329703963950551ns][19371362065ns][info ][gc,stats         ] 
[19.371s][12329703963955288ns][19371366807ns][info ][gc,stats         ]   Allocation tracing is disabled, use -XX:+ShenandoahAllocationTrace to enable.
[19.371s][12329703963970917ns][19371382595ns][info ][safepoint        ] Application time: 0.0262462 seconds
[19.371s][12329703964055021ns][19371466682ns][info ][safepoint,cleanup] deflating idle monitors, 0.0000003 secs
[19.371s][12329703964065053ns][19371476569ns][info ][safepoint,cleanup] updating inline caches, 0.0000021 secs
[19.371s][12329703964070559ns][19371482063ns][info ][safepoint,cleanup] compilation policy safepoint handler, 0.0000002 secs
[19.371s][12329703964075557ns][19371487075ns][info ][safepoint,cleanup] purging class loader data graph, 0.0000001 secs
[19.371s][12329703964080596ns][19371492110ns][info ][safepoint,cleanup] resizing system dictionaries, 0.0000001 secs
INFO: Deflate: InCirc=33 InUse=31 Scavenged=2 ForceMonitorScavenge=0 : pop=1778 free=698
[19.372s][12329703964089515ns][19371501047ns][info ][safepoint,cleanup] safepoint cleanup tasks, 0.0000933 secs
[19.372s][12329703964097813ns][19371509302ns][debug][vmoperation      ] begin VM_Operation (0x00007fb0fbefd480): Exit, mode: safepoint, requested by thread 0x00007fb0f4001720
          vmop                            [ threads:    total initially_running wait_to_block ][ time:    spin   block    sync cleanup    vmop ] page_trap_count
  19.371: Exit                            [                81                 0             0 ][             0       0       0       0     312 ]               0 

Polling page always armed
PrintThreads                       1
FindDeadlocks                      1
Deoptimize                        31
PrintJNI                           1
CollectForMetadataAllocation       136
Exit                               1
ICBufferFull                       4
    0 VM operations coalesced during safepoint
Maximum sync time      0 ms
Maximum vm operation time (except for Exit VM operation)      7 ms
Exit status is 255

This was the command-line used to start the application:

/home/tetest/TE/system/jdk/shenandoah/bin/te_cd1 -cp /home/tetest/TE/system/tmp/9.2.0-cd1-shenandoah-c2220b10a8bfb69fce208f1c72546529.jar  -server -Xms2400M -Xmx4800M -XX:+PrintFlagsFinal -Xlog:gc*=info,safepoint*=info
,vmoperation*=trace:stdout:uptime,uptimenanos,timenanos,level,tags -XX:+UnlockExperimentalVMOptions -XX:SyncKnobs=Verbose=1 -XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1 -XX:+SafepointTimeout -XX:SafepointTime
outDelay=1 --add-modules java.xml.bind --add-exports java.management/com.sun.jmx.mbeanserver=ALL-UNNAMED --add-exports java.base/sun.nio.ch=ALL-UNNAMED  -XX:+UseShenandoahGC -XX:ConcGCThreads=8 -XX:ParallelGCThreads=4 -XX:Monitor
Bound=20000 -XX:-UseBiasedLocking -XX:+DoEscapeAnalysis -XX:+UseNUMA -XX:+UseShenandoahMatrix -XX:+UnlockExperimentalVMOptions -XX:ShenandoahGCHeuristics=traversal -DRoundRobinPrio=0 -DHibernate3=true -DdumpConfig=VALUE  -Djava.net.preferIPv4Stack=true -Djava.util.prefs.systemRoot=/home/tetest com.cinnober.framework.server.impl.FwStart --stdouttolog --stderrtolog -s CD1 -r http://frank-10g.cinnober.com:22780 -i TE -v com.cinnober.common.version.TeVersion

Best regards,

/Lennart