[CONFSERVER-79961] As an admin, I want date timestamps in Garbage Collection Logging to be enabled by default

Type: Suggestion
Resolution: Fixed
Fix Version/s: 8.0.0
Component/s: Server - Installer / Setup
Labels:

Feedback Policy:

We collect Confluence feedback from various sources, and we evaluate what we've collected when planning our product roadmap. To understand how this piece of feedback will be reviewed, see our Implementation of New Features Policy.

Problem Definition

The default Java 11 Garbage Collection Logging settings do not specify any custom sets of decorators.

...
CATALINA_OPTS="-Xloggc:$LOGBASEABS/logs/gc-`date +%F_%H-%M-%S`.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=2M ${CATALINA_OPTS}"
...

As a result, default decorators would then be used - uptime, level, and tags. Please refer to the sample GC log snippet below:

...
[1.374s][debug][gc,age] GC(0) Desired survivor size 3670016 bytes, new threshold 15 (max threshold 15)
[1.583s][debug][gc,age] GC(1) Desired survivor size 3670016 bytes, new threshold 1 (max threshold 15)
[2.020s][debug][gc,age] GC(2) Desired survivor size 17825792 bytes, new threshold 15 (max threshold 15)
[2.767s][debug][gc,age] GC(4) Desired survivor size 18350080 bytes, new threshold 15 (max threshold 15)
[4.238s][debug][gc,age] GC(5) Desired survivor size 22020096 bytes, new threshold 15 (max threshold 15)
...

Workaround

Modify the <Confluence-Installation>/bin/setenv.sh file as follow:

From:

CATALINA_OPTS="-Xlog:gc+age=debug:file=$LOGBASEABS/logs/gc-`date +%F_%H-%M-%S`.log::filecount=5,filesize=2M ${CATALINA_OPTS}"

To:

CATALINA_OPTS="-Xlog:gc*:file=$LOGBASEABS/logs/gc-%t.log:tags,time,uptime,level:filecount=5,filesize=2M ${CATALINA_OPTS}"

is related to

CONFSERVER-61415 Java 11 Garbage Collection Logging Settings Are Not Correctly Applied on Confluence Start

Closed

relates to

CONFSERVER-79959 The default Java 11 Garbage Collection Logging Settings has the wrong syntax for filecount and filesize

Closed

mentioned in: Page Failed to load; Page Failed to load; Page Failed to load

Sen Geronimo made changes - 31/Jan/2023 2:51 AM

Workflow

Original: JAC Suggestion Workflow 4 [ 4296163 ]

New: JAC Suggestion Workflow 3 [ 4341413 ]

Jen Marfell (Inactive) made changes - 14/Dec/2022 2:02 AM

Labels

Original: blocking-8.0 blocking-8.0-beta conf-dc-phoenix fireball

New: blocking-8.0 blocking-8.0-beta conf-dc-phoenix fireball phoenix-conf-dc

James Whitehead made changes - 29/Nov/2022 4:27 AM

Resolution		New: Fixed [ 1 ]
Status	Original: Waiting for Release [ 12075 ]	New: Closed [ 6 ]

James Whitehead made changes - 21/Nov/2022 1:34 AM

Link

New: This issue is related to ~~CONFSERVER-61415~~ [ ~~CONFSERVER-61415~~ ]

James Whitehead made changes - 21/Nov/2022 1:34 AM

Link

Original: This issue relates to ~~CONFSERVER-61415~~ [ ~~CONFSERVER-61415~~ ]

James Whitehead made changes - 21/Nov/2022 1:33 AM

Link

New: This issue relates to ~~CONFSERVER-61415~~ [ ~~CONFSERVER-61415~~ ]

Damien Tan made changes - 17/Nov/2022 12:43 AM

Description

Original: h3. Problem Definition
The default Java 11 Garbage Collection Logging settings do not specify any [custom sets of decorators|https://docs.oracle.com/en/java/javase/11/tools/java.html#GUID-BE93ABDC-999C-4CB5-A88B-1994AAAC74D5__DECORATIONS-A7A4AD31].
{code}
...
CATALINA_OPTS="-Xloggc:$LOGBASEABS/logs/gc-`date +%F_%H-%M-%S`.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=2M ${CATALINA_OPTS}"
...
{code}
As a result, default decorators would then be used - _uptime_, _level_, and _tags_. Please refer to the sample GC log snippet below:
{code}
...
[1.374s][debug][gc,age] GC(0) Desired survivor size 3670016 bytes, new threshold 15 (max threshold 15)
[1.583s][debug][gc,age] GC(1) Desired survivor size 3670016 bytes, new threshold 1 (max threshold 15)
[2.020s][debug][gc,age] GC(2) Desired survivor size 17825792 bytes, new threshold 15 (max threshold 15)
[2.767s][debug][gc,age] GC(4) Desired survivor size 18350080 bytes, new threshold 15 (max threshold 15)
[4.238s][debug][gc,age] GC(5) Desired survivor size 22020096 bytes, new threshold 15 (max threshold 15)
...
{code}

h3. Suggested Solution
To specify a set of decorators in the default Confluence's GC logging as well as to add _time_ decorator, to show current time and date in ISO-8601 format.
(on) This would be very helpful in troubleshooting performance related issues in Confluence.

h3. Workaround
Modify the {{<Confluence-Installation>/bin/setenv.sh}} file as follow:
{code:title=From:}
CATALINA_OPTS="-Xlog:gc+age=debug:file=$LOGBASEABS/logs/gc-`date +%F_%H-%M-%S`.log::filecount=5,filesize=2M ${CATALINA_OPTS}"
{code}
{code:title=To:}
CATALINA_OPTS="-Xlog:gc+age=debug:file=$LOGBASEABS/logs/gc-`date +%F_%H-%M-%S`.log:tags,time,uptime,level:filecount=5,filesize=2M ${CATALINA_OPTS}"
{code}

New: h3. Problem Definition
The default Java 11 Garbage Collection Logging settings do not specify any [custom sets of decorators|https://docs.oracle.com/en/java/javase/11/tools/java.html#GUID-BE93ABDC-999C-4CB5-A88B-1994AAAC74D5__DECORATIONS-A7A4AD31].
{code}
...
CATALINA_OPTS="-Xloggc:$LOGBASEABS/logs/gc-`date +%F_%H-%M-%S`.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=2M ${CATALINA_OPTS}"
...
{code}
As a result, default decorators would then be used - _uptime_, _level_, and _tags_. Please refer to the sample GC log snippet below:
{code}
...
[1.374s][debug][gc,age] GC(0) Desired survivor size 3670016 bytes, new threshold 15 (max threshold 15)
[1.583s][debug][gc,age] GC(1) Desired survivor size 3670016 bytes, new threshold 1 (max threshold 15)
[2.020s][debug][gc,age] GC(2) Desired survivor size 17825792 bytes, new threshold 15 (max threshold 15)
[2.767s][debug][gc,age] GC(4) Desired survivor size 18350080 bytes, new threshold 15 (max threshold 15)
[4.238s][debug][gc,age] GC(5) Desired survivor size 22020096 bytes, new threshold 15 (max threshold 15)
...
{code}

h3. Suggested Solution
To specify a set of decorators in the default Confluence's GC logging as well as to add _time_ decorator, to show current time and date in ISO-8601 format.
(on) This would be very helpful in troubleshooting performance related issues in Confluence.

h3. Workaround
Modify the {{<Confluence-Installation>/bin/setenv.sh}} file as follow:
{code:title=From:}
CATALINA_OPTS="-Xlog:gc+age=debug:file=$LOGBASEABS/logs/gc-`date +%F_%H-%M-%S`.log::filecount=5,filesize=2M ${CATALINA_OPTS}"
{code}
{code:title=To:}
CATALINA_OPTS="-Xlog:gc*:file=$LOGBASEABS/logs/gc-%t.log:tags,time,uptime,level:filecount=5,filesize=2M ${CATALINA_OPTS}"
{code}

Alex Blekhman (Inactive) made changes - 10/Nov/2022 2:01 AM

QA Demo Status	Original: Not Done [ 14330 ]	New: Done [ 14331 ]
QA Kickoff Status	Original: Not Done [ 14234 ]	New: Done [ 14235 ]
Testing Notes		New: Tested Confluence Distribution with the fixed GC logging and confirmed it looks as desired. {noformat} [2022-11-09T08:42:36.265+0000][0.008s][info][gc,heap] Heap region size: 1M [2022-11-09T08:42:36.297+0000][0.031s][info][gc ] Using G1 [2022-11-09T08:42:36.297+0000][0.031s][info][gc,heap,coops] Heap address: 0x00000000c0000000, size: 1024 MB, Compressed Oops mode: 32-bit [2022-11-09T08:42:37.968+0000][1.700s][info][gc,start ] GC(0) Pause Young (Normal) (G1 Evacuation Pause) [2022-11-09T08:42:37.968+0000][1.700s][info][gc,task ] GC(0) Using 2 workers of 2 for evacuation [2022-11-09T08:42:38.000+0000][1.733s][info][gc,phases ] GC(0) Pre Evacuate Collection Set: 0.0ms [2022-11-09T08:42:38.000+0000][1.734s][info][gc,phases ] GC(0) Evacuate Collection Set: 32.0ms [2022-11-09T08:42:38.000+0000][1.734s][info][gc,phases ] GC(0) Post Evacuate Collection Set: 0.7ms [2022-11-09T08:42:38.000+0000][1.734s][info][gc,phases ] GC(0) Other: 0.4ms [2022-11-09T08:42:38.000+0000][1.734s][info][gc,heap ] GC(0) Eden regions: 51->0(44) [2022-11-09T08:42:38.000+0000][1.734s][info][gc,heap ] GC(0) Survivor regions: 0->7(7) [2022-11-09T08:42:38.000+0000][1.734s][info][gc,heap ] GC(0) Old regions: 0->3 [2022-11-09T08:42:38.000+0000][1.734s][info][gc,heap ] GC(0) Humongous regions: 1->1 [2022-11-09T08:42:38.000+0000][1.734s][info][gc,metaspace ] GC(0) Metaspace: 18030K->18030K(1067008K) [2022-11-09T08:42:38.000+0000][1.734s][info][gc ] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 52M->10M(1024M) 33.911ms [2022-11-09T08:42:38.000+0000][1.734s][info][gc,cpu ] GC(0) User=0.06s Sys=0.00s Real=0.03s [2022-11-09T08:42:38.506+0000][2.238s][info][gc,start ] GC(1) Pause Young (Normal) (G1 Evacuation Pause) [2022-11-09T08:42:38.506+0000][2.238s][info][gc,task ] GC(1) Using 2 workers of 2 for evacuation [2022-11-09T08:42:38.522+0000][2.258s][info][gc,phases ] GC(1) Pre Evacuate Collection Set: 0.0ms [2022-11-09T08:42:38.522+0000][2.258s][info][gc,phases ] GC(1) Evacuate Collection Set: 19.1ms [2022-11-09T08:42:38.522+0000][2.258s][info][gc,phases ] GC(1) Post Evacuate Collection Set: 0.4ms [2022-11-09T08:42:38.522+0000][2.258s][info][gc,phases ] GC(1) Other: 0.1ms [2022-11-09T08:42:38.522+0000][2.258s][info][gc,heap ] GC(1) Eden regions: 44->0(44) [2022-11-09T08:42:38.522+0000][2.258s][info][gc,heap ] GC(1) Survivor regions: 7->7(7) [2022-11-09T08:42:38.522+0000][2.258s][info][gc,heap ] GC(1) Old regions: 3->15 [2022-11-09T08:42:38.522+0000][2.258s][info][gc,heap ] GC(1) Humongous regions: 10->5 [2022-11-09T08:42:38.522+0000][2.258s][info][gc,metaspace ] GC(1) Metaspace: 18760K->18760K(1067008K) {noformat}
Status	Original: In Progress [ 3 ]	New: Waiting for Release [ 12075 ]

Jen Marfell (Inactive) made changes - 10/Nov/2022 12:50 AM

Fix Version/s

New: 8.0.0 [ 101718 ]

Alex Blekhman (Inactive) made changes - 09/Nov/2022 5:38 AM

Status

Original: Reviewing [ 11773 ]

New: In Progress [ 3 ]

Assignee:: Alex Blekhman (Inactive)

Reporter:: Lauretha Rura

Votes:: 0 Vote for this issue

Watchers:: 3 Start watching this issue

Created:: 16/Sep/2022 5:01 AM

Updated:: 14/Dec/2022 2:02 AM

Resolved:: 29/Nov/2022 4:27 AM

Confluence Data Center

Details

Description

Problem Definition

Suggested Solution

Workaround

Attachments

Issue Links

Forms

Activity

People

Dates