JMC-5002: Put JVM Start Time in perspective

[Marcus Hirt]

Looks good!

 

/M

 

From: Ken Dobson <kdobson at redhat.com>
Date: Wednesday, 9 January 2019 at 20:57
To: Marcus Hirt <marcus.hirt at oracle.com>
Cc: <jmc-dev at openjdk.java.net>
Subject: Re: JMC-5002: Put JVM Start Time in perspective

 

Sorry forgot to add the modified test to the original patch here it is now. Nothing else has changed just need a quick approval on the test update.

 

Thanks, 

 

Ken Dobson

 

 

diff --git a/core/org.openjdk.jmc.flightrecorder.rules.jdk/src/main/java/org/openjdk/jmc/flightrecorder/rules/jdk/memory/IncreasingLiveSetRule.java b/core/org.openjdk.jmc.flightrecorder.rules.jdk/src/main/java/org/openjdk/jmc/flightrecorder/rules/jdk/memory/IncreasingLiveSetRule.java
--- a/core/org.openjdk.jmc.flightrecorder.rules.jdk/src/main/java/org/openjdk/jmc/flightrecorder/rules/jdk/memory/IncreasingLiveSetRule.java
+++ b/core/org.openjdk.jmc.flightrecorder.rules.jdk/src/main/java/org/openjdk/jmc/flightrecorder/rules/jdk/memory/IncreasingLiveSetRule.java
@@ -57,6 +57,7 @@
 import org.openjdk.jmc.common.item.IMemberAccessor;
 import org.openjdk.jmc.common.item.ItemFilters;
 import org.openjdk.jmc.common.unit.BinaryPrefix;
+import org.openjdk.jmc.common.unit.DecimalPrefix;
 import org.openjdk.jmc.common.unit.IQuantity;
 import org.openjdk.jmc.common.unit.UnitLookup;
 import org.openjdk.jmc.common.util.IPreferenceValueProvider;
@@ -134,11 +135,13 @@
         EventAvailability ea = RulesToolkit.getEventAvailability(items, JdkTypeIDs.OLD_OBJECT_SAMPLE);
         // FIXME: Should construct an message using memoryIncrease, not use a hard limit
         if (score >= 25 && (ea == EventAvailability.DISABLED || ea == EventAvailability.UNKNOWN)) {
+            IQuantity timeAfterJVMStart = items.getAggregate(JdkAggregators.FIRST_ITEM_START).subtract(items.getAggregate(JdkAggregators.JVM_START_TIME));
             String shortMessage = MessageFormat.format(
                     Messages.getString(Messages.IncreasingLiveSetRuleFactory_TEXT_INFO),
                     liveSetIncreasePerSecond.displayUsing(IDisplayable.AUTO));
             String longMessage = shortMessage + "<p>" //$NON-NLS-1$
-                    + Messages.getString(Messages.IncreasingLiveSetRuleFactory_TEXT_INFO_LONG);
+                    + MessageFormat.format(Messages.getString(Messages.IncreasingLiveSetRuleFactory_TEXT_INFO_LONG),
+                            timeAfterJVMStart.displayUsing(IDisplayable.AUTO));
             return new Result(this, score, shortMessage, longMessage, JdkQueries.HEAP_SUMMARY_AFTER_GC);
         } else if (score < 25) {
             return new Result(this, score, Messages.getString(Messages.IncreasingLiveSetRule_TEXT_OK));
diff --git a/core/org.openjdk.jmc.flightrecorder.rules.jdk/src/main/resources/org/openjdk/jmc/flightrecorder/rules/jdk/messages/internal/messages.properties b/core/org.openjdk.jmc.flightrecorder.rules.jdk/src/main/resources/org/openjdk/jmc/flightrecorder/rules/jdk/messages/internal/messages.properties
--- a/core/org.openjdk.jmc.flightrecorder.rules.jdk/src/main/resources/org/openjdk/jmc/flightrecorder/rules/jdk/messages/internal/messages.properties
+++ b/core/org.openjdk.jmc.flightrecorder.rules.jdk/src/main/resources/org/openjdk/jmc/flightrecorder/rules/jdk/messages/internal/messages.properties
@@ -374,7 +374,7 @@
 IncreasingLiveSetRuleFactory_RULE_NAME=Heap Live Set Trend
 # {0} is a number denoted in Mebibytes per second
 IncreasingLiveSetRuleFactory_TEXT_INFO=The live set on the heap seems to increase with a speed of about {0} per second during the recording.
-IncreasingLiveSetRuleFactory_TEXT_INFO_LONG=This may be due to a memory leak in the application or it may be an artifact of a short recording. More information can be gathered by using the 'Old Object Sample' event, if available.
+IncreasingLiveSetRuleFactory_TEXT_INFO_LONG=This may be due to a memory leak in the application or it may be an artifact of a short recording if the JVM has recently been started. The recording began {0} after the JVM was started. More information can be gathered by using the 'Old Object Sample' event, if available.
 IncreasingMetaspaceLiveSetRuleFactory_RULE_NAME=Metaspace Live Set Trend
 IncreasingMetaspaceLiveSetRuleFactory_TEXT_INFO=The class data seems to increase constantly in the metaspace during the recording.
 IncreasingMetaspaceLiveSetRuleFactory_TEXT_INFO_LONG=This behavior may indicate a memory leak in the metaspace, this could be due to the application not unloading classes as needed.
diff --git a/core/tests/org.openjdk.jmc.flightrecorder.rules.jdk.test/src/test/resources/baseline/JfrRuleBaseline.xml b/core/tests/org.openjdk.jmc.flightrecorder.rules.jdk.test/src/test/resources/baseline/JfrRuleBaseline.xml
--- a/core/tests/org.openjdk.jmc.flightrecorder.rules.jdk.test/src/test/resources/baseline/JfrRuleBaseline.xml
+++ b/core/tests/org.openjdk.jmc.flightrecorder.rules.jdk.test/src/test/resources/baseline/JfrRuleBaseline.xml
@@ -3888,7 +3888,7 @@
 <severity>Information</severity>
 <score>58.89187525739308</score>
 <shortDescription>The live set on the heap seems to increase with a speed of about 638 KiB per second during the recording.</shortDescription>
-<longDescription>The live set on the heap seems to increase with a speed of about 638 KiB per second during the recording.<p>This may be due to a memory leak in the application or it may be an artifact of a short recording. More information can be gathered by using the 'Old Object Sample' event, if available.</longDescription>
+<longDescription>The live set on the heap seems to increase with a speed of about 638 KiB per second during the recording.<p>This may be due to a memory leak in the application or it may be an artifact of a short recording if the JVM has recently been started. The recording began 3.249 s after the JVM was started. More information can be gathered by using the Old Object Sample event, if available.</longDescription>
 </rule>
 <rule>
 <id>IncreasingMetaSpaceLiveSet</id>

 

 

On Tue, Jan 8, 2019 at 3:33 AM Marcus Hirt <marcus.hirt at oracle.com> wrote:

Hi Ken,

I think it's fine. Please go ahead.

Kind regards,
Marcus

On 2019-01-07, 21:54, "jmc-dev on behalf of Ken Dobson" <jmc-dev-bounces at openjdk.java.net on behalf of kdobson at redhat.com> wrote:

    Hi all,

    This is just a small patch that adds how long a flight recording was
    started after the JVM was started to the rule text for the
    IncreasingLiveSetRule. The wording of the rule text feels a little choppy
    now so if anyone has suggestions they would be appreciated.

    https://bugs.openjdk.java.net/projects/JMC/issues/JMC-5002

    Thanks,

    Ken Dobson

    diff --git
    a/core/org.openjdk.jmc.flightrecorder.rules.jdk/src/main/java/org/openjdk/jmc/flightrecorder/rules/jdk/memory/IncreasingLiveSetRule.java
    b/core/org.openjdk.jmc.flightrecorder.rules.jdk/src/main/java/org/openjdk/jmc/flightrecorder/rules/jdk/memory/IncreasingLiveSetRule.java
    ---
    a/core/org.openjdk.jmc.flightrecorder.rules.jdk/src/main/java/org/openjdk/jmc/flightrecorder/rules/jdk/memory/IncreasingLiveSetRule.java
    +++
    b/core/org.openjdk.jmc.flightrecorder.rules.jdk/src/main/java/org/openjdk/jmc/flightrecorder/rules/jdk/memory/IncreasingLiveSetRule.java
    @@ -57,6 +57,7 @@
     import org.openjdk.jmc.common.item.IMemberAccessor;
     import org.openjdk.jmc.common.item.ItemFilters;
     import org.openjdk.jmc.common.unit.BinaryPrefix;
    +import org.openjdk.jmc.common.unit.DecimalPrefix;
     import org.openjdk.jmc.common.unit.IQuantity;
     import org.openjdk.jmc.common.unit.UnitLookup;
     import org.openjdk.jmc.common.util.IPreferenceValueProvider;
    @@ -134,11 +135,13 @@
             EventAvailability ea = RulesToolkit.getEventAvailability(items,
    JdkTypeIDs.OLD_OBJECT_SAMPLE);
             // FIXME: Should construct an message using memoryIncrease, not
    use a hard limit
             if (score >= 25 && (ea == EventAvailability.DISABLED || ea ==
    EventAvailability.UNKNOWN)) {
    +            IQuantity timeAfterJVMStart =
    items.getAggregate(JdkAggregators.FIRST_ITEM_START).subtract(items.getAggregate(JdkAggregators.JVM_START_TIME));
                 String shortMessage = MessageFormat.format(

    Messages.getString(Messages.IncreasingLiveSetRuleFactory_TEXT_INFO),

    liveSetIncreasePerSecond.displayUsing(IDisplayable.AUTO));
                 String longMessage = shortMessage + "<p>" //$NON-NLS-1$
    -                    +
    Messages.getString(Messages.IncreasingLiveSetRuleFactory_TEXT_INFO_LONG);
    +                    +
    MessageFormat.format(Messages.getString(Messages.IncreasingLiveSetRuleFactory_TEXT_INFO_LONG),
    +
    timeAfterJVMStart.displayUsing(IDisplayable.AUTO));
                 return new Result(this, score, shortMessage, longMessage,
    JdkQueries.HEAP_SUMMARY_AFTER_GC);
             } else if (score < 25) {
                 return new Result(this, score,
    Messages.getString(Messages.IncreasingLiveSetRule_TEXT_OK));
    diff --git
    a/core/org.openjdk.jmc.flightrecorder.rules.jdk/src/main/resources/org/openjdk/jmc/flightrecorder/rules/jdk/messages/internal/messages.properties
    b/core/org.openjdk.jmc.flightrecorder.rules.jdk/src/main/resources/org/openjdk/jmc/flightrecorder/rules/jdk/messages/internal/messages.properties
    ---
    a/core/org.openjdk.jmc.flightrecorder.rules.jdk/src/main/resources/org/openjdk/jmc/flightrecorder/rules/jdk/messages/internal/messages.properties
    +++
    b/core/org.openjdk.jmc.flightrecorder.rules.jdk/src/main/resources/org/openjdk/jmc/flightrecorder/rules/jdk/messages/internal/messages.properties
    @@ -368,7 +368,7 @@
     IncreasingLiveSetRuleFactory_RULE_NAME=Heap Live Set Trend
     # {0} is a number denoted in Mebibytes per second
     IncreasingLiveSetRuleFactory_TEXT_INFO=The live set on the heap seems to
    increase with a speed of about {0} per second during the recording.
    -IncreasingLiveSetRuleFactory_TEXT_INFO_LONG=This may be due to a memory
    leak in the application or it may be an artifact of a short recording. More
    information can be gathered by using the 'Old Object Sample' event, if
    available.
    +IncreasingLiveSetRuleFactory_TEXT_INFO_LONG=This may be due to a memory
    leak in the application or it may be an artifact of a short recording if
    the JVM has recently been started. The recording began {0} after the JVM
    was started. More information can be gathered by using the 'Old Object
    Sample' event, if available.
     IncreasingMetaspaceLiveSetRuleFactory_RULE_NAME=Metaspace Live Set Trend
     IncreasingMetaspaceLiveSetRuleFactory_TEXT_INFO=The class data seems to
    increase constantly in the metaspace during the recording.
     IncreasingMetaspaceLiveSetRuleFactory_TEXT_INFO_LONG=This behavior may
    indicate a memory leak in the metaspace, this could be due to the
    application not unloading classes as needed.