[
https://issues.apache.org/jira/browse/CASSANDRA-9124?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14487007#comment-14487007
]
Robert Stupp commented on CASSANDRA-9124:
-----------------------------------------
One nit: unused import
The list of GCs is consistent with the names mentioned in
{{hotspot/src/share/vm/services/memoryManager.hpp}}.
You can replace the multiple hash maps ({{gctimes}} + {{beans}}), collections
and sorting and move it all to the GCInspector constructor by introducing a
static inner class holding the reference to {{GarbageCollectorMXBean}}, the
{{previousTotal}} and the sorted list of {{keys}}. Also take care of calling
{{GcInfo#getMemoryUsageBeforeGc}} since it always creates an unmodifiable
instance of the underlying map.
The comment (_full collection_) above the call to
{{SSTableDeletingTask.rescheduleFailedTasks()}} is (hopefully) not true. Can
you change that?
In order to track application stopped time (which is not reported by the JMX
beans), we could do something like this added to the static initializer of
{{GCInspector}}.
{code}
Thread stwTracker = new Thread()
{
public void run()
{
while (true)
{
long t0 = System.nanoTime();
try
{
Thread.sleep(1);
}
catch (InterruptedException e)
{
break;
}
long t1 = System.nanoTime();
long t = (t1 - t0) / 1000000;
if (t > 1)
stwTimeInaccurate.addAndGet(t);
}
}
};
stwTracker.setDaemon(true);
stwTracker.setName("GC STW tracker");
stwTracker.start();
{code}
A quick experiment showed that (with ParNew/CMS) that approach works nicely and
gives about the same results as {{-XX:+PrintGCApplicationStoppedTime}}.
Just a note: during a concurrent collection it might occur that
{{after.getUsed()}} returns a higher value than {{before.getUsed()}}. But
unfortunately that GCInfo thing does not provide something like
{{getCollectedBytes()}}. So we should make that clear by renaming the field
{{State.totalBytesReclaimed}}.
PS:
I used this code to force a lot of GCs in new+old gen in a 1GB VM:
{code}
new Thread() {
public void run()
{
List<byte[]> l = new ArrayList<>();
while (true)
{
for (int i = 0; i < 1000; i++)
l.add(new byte[1024]);
try
{
Thread.sleep(250);
}
catch (InterruptedException e)
{
e.printStackTrace();
}
l.clear();
}
}
}.start();
new Thread() {
public void run()
{
List<byte[]> l = new ArrayList<>();
while (true)
{
for (int i = 0; i < 2; i++)
l.add(new byte[64 * 1024 * 1024]);
try
{
Thread.sleep(250);
}
catch (InterruptedException e)
{
e.printStackTrace();
}
l.clear();
}
}
}.start();
{code}
> GCInspector logs very different times after CASSANDRA-7638
> ----------------------------------------------------------
>
> Key: CASSANDRA-9124
> URL: https://issues.apache.org/jira/browse/CASSANDRA-9124
> Project: Cassandra
> Issue Type: Bug
> Components: Core
> Reporter: Jeremiah Jordan
> Assignee: Ariel Weisberg
> Priority: Minor
> Fix For: 3.0, 2.1.5
>
>
> After the GCInspector rewrite in CASSANDRA-7638 the times reported for CMS
> are the full time (including all the concurrent time), not just the stop the
> world pause time. In previous versions we reported just the stop the world
> pause time. This change is kind of scary for someone used to the old logs,
> and is also not as useful. You can't get "how long were things really
> stopped" from the log message any more.
> For example, this is a CMS that got logged in C* 2.1:
> {noformat}
> INFO [Service Thread] 2015-04-03 23:58:37,583 GCInspector.java:142 -
> ConcurrentMarkSweep GC in 12926ms. CMS Old Gen: 5305346280 -> 1106799064;
> Par Eden Space: 223080 -> 158423560; Par Survivor Space: 42081744 -> 51339584
> {noformat}
> And here is the corresponding information for that CMS from the gc log.
> {noformat}
> 2015-04-03T23:58:24.656+0000: 8064.780: [GC [1 CMS-initial-mark:
> 5181002K(6901760K)] 5222315K(7639040K), 0.0316710 secs] [Times: user=0.03
> sys=0.00, real=0.03 secs]
> 2015-04-03T23:58:24.688+0000: 8064.812: Total time for which application
> threads were stopped: 0.0324490 seconds
> 2015-04-03T23:58:24.688+0000: 8064.812: [CMS-concurrent-mark-start]
> 2015-04-03T23:58:26.939+0000: 8067.062: [CMS-concurrent-mark: 2.176/2.250
> secs] [Times: user=12.94 sys=1.73, real=2.25 secs]
> 2015-04-03T23:58:26.939+0000: 8067.063: [CMS-concurrent-preclean-start]
> 2015-04-03T23:58:27.209+0000: 8067.333: [CMS-concurrent-preclean: 0.187/0.270
> secs] [Times: user=1.53 sys=0.15, real=0.28 secs]
> 2015-04-03T23:58:27.210+0000: 8067.333:
> [CMS-concurrent-abortable-preclean-start]
> 2015-04-03T23:58:27.988+0000: 8068.112: [CMS-concurrent-abortable-preclean:
> 0.759/0.779 secs] [Times: user=4.07 sys=0.74, real=0.77 secs]
> 2015-04-03T23:58:27.989+0000: 8068.113: [GC[YG occupancy: 488441 K (737280
> K)]2015-04-03T23:58:27.989+0000: 8068.113: [Rescan (parallel) , 0.3688960
> secs]2015-04-03T23:58:28.358+0000: 8068.482: [weak refs processing, 0.0009620
> secs]2015-04-03T23:58:28.359+0000: 8068.483: [class unloading, 0.0060870
> secs]2015-04-03T23:58:28.365+0000: 8068.489: [scrub symbol table, 0.0146010
> secs]2015-04-03T23:58:28.380+0000: 8068.504: [scrub string table, 0.0031270
> secs] [1 CMS-remark: 5231445K(6901760K)] 5719886K(7639040K), 0.3953770 secs]
> [Times: user=2.96 sys=0.00, real=0.39 secs]
> 2015-04-03T23:58:28.385+0000: 8068.508: Total time for which application
> threads were stopped: 0.3962470 seconds
> 2015-04-03T23:58:28.385+0000: 8068.509: [CMS-concurrent-sweep-start]
> 2015-04-03T23:58:37.582+0000: 8077.706: [CMS-concurrent-sweep: 8.661/9.197
> secs] [Times: user=44.80 sys=9.58, real=9.20 secs]
> 2015-04-03T23:58:37.589+0000: 8077.713: [CMS-concurrent-reset-start]
> 2015-04-03T23:58:37.633+0000: 8077.757: [CMS-concurrent-reset: 0.044/0.044
> secs] [Times: user=0.19 sys=0.10, real=0.04 secs]
> {noformat}
> The entire CMS took the 12 seconds reported in the GCIspector log message.
> Previously we would have only reported the 0.39 seconds that were spent in
> STW pauses.
> At the least we need to change the log message so that people don't think we
> are still just reporting STW time. But it would be more helpful if we could
> get the STW time and put that into the log message like we had previously.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
