Skip to content

Conversation

halibobo1205
Copy link
Contributor

@halibobo1205 halibobo1205 commented Sep 24, 2025

What does this PR do?

This PR optimizes the JVM garbage collection logging parameters to reduce log verbosity and improve file management efficiency.

Changes:

  • Reduced GC log scope from gc* to gc,gc+heap
  • Decreased file rotation count from 50 to 10 files
  • Simplified log format by removing redundant uptime field
  • Keep readme, start.sh.simple, and java-tron.vmoptions the same.

Before:

-Xlog:gc*:file=gc.log:time,uptime,level,tags:filecount=50,filesize=100M

After:

-Xlog:gc,gc+heap:file=gc.log:time,tags,level:filecount=10,filesize=100M

Why are these changes required?

  1. Excessive Log Volume: Current gc* configuration generates verbose logs with detailed phase information, task details, and metaspace data that are rarely needed for routine monitoring
  2. Disk Space Waste: 50 rotated files consuming up to 5GB of disk space is excessive for most use cases
  3. Log Management Overhead: A Large number of log files makes maintenance and analysis more difficult
  4. Performance Impact: Writing excessive log data can impact application performance

Benefits:

  • 80% reduction in disk usage (from ~5GB to ~1GB)
  • Cleaner, more readable logs focused on essential metrics
  • Retained all critical GC performance indicators

This PR has been tested by:

  • Unit Tests:
  • Manual Testing:

Follow up

Extra details

Log Content Comparison:

Current verbose output (gc):*

[2025-08-29T02:57:52.859+0000][159783.411s][info][gc,ref      ] GC(30998) Soft: 2409 encountered, 2058 discovered, 0 enqueued
[2025-08-29T02:57:52.859+0000][159783.411s][info][gc,ref      ] GC(30998) Weak: 3700 encountered, 219 discovered, 2 enqueued
[2025-08-29T02:57:52.859+0000][159783.411s][info][gc,ref      ] GC(30998) Final: 169 encountered, 4 discovered, 0 enqueued
[2025-08-29T02:57:52.860+0000][159783.411s][info][gc,ref      ] GC(30998) Phantom: 36 encountered, 27 discovered, 0 enqueued
[2025-08-29T02:57:52.860+0000][159783.411s][info][gc,reloc    ] GC(30998) Small Pages: 1011 / 2022M, Empty: 182M, Relocated: 10M, In-Place: 0
[2025-08-29T02:57:52.860+0000][159783.411s][info][gc,reloc    ] GC(30998) Medium Pages: 1 / 32M, Empty: 0M, Relocated: 0M, In-Place: 0
[2025-08-29T02:57:52.860+0000][159783.411s][info][gc,reloc    ] GC(30998) Large Pages: 3 / 122M, Empty: 0M, Relocated: 0M, In-Place: 0
[2025-08-29T02:57:52.860+0000][159783.411s][info][gc,reloc    ] GC(30998) Forwarding Usage: 3M
[2025-08-29T02:57:52.860+0000][159783.411s][info][gc,heap     ] GC(30998) Min Capacity: 8M(0%)
[2025-08-29T02:57:52.860+0000][159783.411s][info][gc,heap     ] GC(30998) Max Capacity: 18432M(100%)
[2025-08-29T02:57:52.860+0000][159783.411s][info][gc,heap     ] GC(30998) Soft Max Capacity: 18432M(100%)
[2025-08-29T02:57:52.860+0000][159783.411s][info][gc,heap     ] GC(30998)                Mark Start          Mark End        Relocate Start      Relocate End           High               Low
[2025-08-29T02:57:52.860+0000][159783.411s][info][gc,heap     ] GC(30998)  Capacity:     2230M (12%)        2230M (12%)        2230M (12%)        2230M (12%)        2230M (12%)        2230M (12%)
[2025-08-29T02:57:52.860+0000][159783.411s][info][gc,heap     ] GC(30998)      Free:    16256M (88%)       16250M (88%)       16432M (89%)       18142M (98%)       18142M (98%)       16250M (88%)
[2025-08-29T02:57:52.860+0000][159783.411s][info][gc,heap     ] GC(30998)      Used:     2176M (12%)        2182M (12%)        2000M (11%)         290M (2%)         2182M (12%)         290M (2%)
[2025-08-29T02:57:52.860+0000][159783.411s][info][gc,heap     ] GC(30998)      Live:         -               228M (1%)          228M (1%)          228M (1%)             -                  -
[2025-08-29T02:57:52.860+0000][159783.411s][info][gc,heap     ] GC(30998) Allocated:         -                 6M (0%)            6M (0%)            5M (0%)             -                  -
[2025-08-29T02:57:52.860+0000][159783.411s][info][gc,heap     ] GC(30998)   Garbage:         -              1947M (11%)        1765M (10%)          55M (0%)             -                  -
[2025-08-29T02:57:52.860+0000][159783.411s][info][gc,heap     ] GC(30998) Reclaimed:         -                  -               182M (1%)         1891M (10%)            -                  -
[2025-08-29T02:57:52.860+0000][159783.411s][info][gc          ] GC(30998) Garbage Collection (Proactive) 2176M(12%)->290M(2%)
[2025-08-29T02:57:59.281+0000][159789.832s][info][gc,start    ] GC(30999) Garbage Collection (Proactive)
[2025-08-29T02:57:59.281+0000][159789.832s][info][gc,task     ] GC(30999) Using 4 workers
[2025-08-29T02:57:59.281+0000][159789.832s][info][gc,phases   ] GC(30999) Pause Mark Start 0.016ms
[2025-08-29T02:57:59.342+0000][159789.894s][info][gc,phases   ] GC(30999) Concurrent Mark 61.207ms
[2025-08-29T02:57:59.342+0000][159789.894s][info][gc,phases   ] GC(30999) Pause Mark End 0.011ms
[2025-08-29T02:57:59.342+0000][159789.894s][info][gc,phases   ] GC(30999) Concurrent Mark Free 0.000ms
[2025-08-29T02:57:59.351+0000][159789.902s][info][gc,phases   ] GC(30999) Concurrent Process Non-Strong References 8.386ms
[2025-08-29T02:57:59.351+0000][159789.902s][info][gc,phases   ] GC(30999) Concurrent Reset Relocation Set 0.043ms
[2025-08-29T02:57:59.354+0000][159789.905s][info][gc,phases   ] GC(30999) Concurrent Select Relocation Set 3.176ms
[2025-08-29T02:57:59.354+0000][159789.905s][info][gc,phases   ] GC(30999) Pause Relocate Start 0.006ms
[2025-08-29T02:57:59.358+0000][159789.910s][info][gc,phases   ] GC(30999) Concurrent Relocate 4.167ms
[2025-08-29T02:57:59.358+0000][159789.910s][info][gc,load     ] GC(30999) Load: 0.23/0.31/0.39
[2025-08-29T02:57:59.358+0000][159789.910s][info][gc,mmu      ] GC(30999) MMU: 2ms/97.5%, 5ms/99.0%, 10ms/99.5%, 20ms/99.7%, 50ms/99.9%, 100ms/99.9%
[2025-08-29T02:57:59.358+0000][159789.910s][info][gc,marking  ] GC(30999) Mark: 4 stripe(s), 2 proactive flush(es), 1 terminate flush(es), 0 completion(s), 0 continuation(s)
[2025-08-29T02:57:59.358+0000][159789.910s][info][gc,marking  ] GC(30999) Mark Stack Usage: 32M
[2025-08-29T02:57:59.358+0000][159789.910s][info][gc,nmethod  ] GC(30999) NMethods: 14155 registered, 3031 unregistered
[2025-08-29T02:57:59.358+0000][159789.910s][info][gc,metaspace] GC(30999) Metaspace: 67M used, 68M committed, 480M reserved
[2025-08-29T02:57:59.358+0000][159789.910s][info][gc,ref      ] GC(30999) Soft: 2409 encountered, 2065 discovered, 0 enqueued
[2025-08-29T02:57:59.358+0000][159789.910s][info][gc,ref      ] GC(30999) Weak: 4167 encountered, 159 discovered, 3 enqueued
[2025-08-29T02:57:59.358+0000][159789.910s][info][gc,ref      ] GC(30999) Final: 169 encountered, 1 discovered, 0 enqueued
[2025-08-29T02:57:59.358+0000][159789.910s][info][gc,ref      ] GC(30999) Phantom: 36 encountered, 27 discovered, 0 enqueued
[2025-08-29T02:57:59.358+0000][159789.910s][info][gc,reloc    ] GC(30999) Small Pages: 1004 / 2008M, Empty: 88M, Relocated: 15M, In-Place: 0
[2025-08-29T02:57:59.358+0000][159789.910s][info][gc,reloc    ] GC(30999) Medium Pages: 1 / 32M, Empty: 0M, Relocated: 0M, In-Place: 0
[2025-08-29T02:57:59.358+0000][159789.910s][info][gc,reloc    ] GC(30999) Large Pages: 3 / 122M, Empty: 0M, Relocated: 0M, In-Place: 0
[2025-08-29T02:57:59.358+0000][159789.910s][info][gc,reloc    ] GC(30999) Forwarding Usage: 5M

New optimized output (gc,gc+heap):

[2025-09-24T07:29:50.624+0000][info][gc,heap] GC(1) Min Capacity: 9216M(50%)
[2025-09-24T07:29:50.624+0000][info][gc,heap] GC(1) Max Capacity: 18432M(100%)
[2025-09-24T07:29:50.624+0000][info][gc,heap] GC(1) Soft Max Capacity: 18432M(100%)
[2025-09-24T07:29:50.624+0000][info][gc,heap] GC(1)                Mark Start          Mark End        Relocate Start      Relocate End           High               Low
[2025-09-24T07:29:50.624+0000][info][gc,heap] GC(1)  Capacity:     9216M (50%)        9216M (50%)        9216M (50%)        9216M (50%)        9216M (50%)        9216M (50%)
[2025-09-24T07:29:50.624+0000][info][gc,heap] GC(1)      Free:    14670M (80%)       14654M (80%)       16138M (88%)       18174M (99%)       18174M (99%)       14652M (79%)
[2025-09-24T07:29:50.624+0000][info][gc,heap] GC(1)      Used:     3762M (20%)        3778M (20%)        2294M (12%)         258M (1%)         3780M (21%)         258M (1%)
[2025-09-24T07:29:50.624+0000][info][gc,heap] GC(1)      Live:         -               197M (1%)          197M (1%)          197M (1%)             -                  -
[2025-09-24T07:29:50.624+0000][info][gc,heap] GC(1) Allocated:         -                16M (0%)           18M (0%)           27M (0%)             -                  -
[2025-09-24T07:29:50.624+0000][info][gc,heap] GC(1)   Garbage:         -              3564M (19%)        2078M (11%)          32M (0%)             -                  -
[2025-09-24T07:29:50.624+0000][info][gc,heap] GC(1) Reclaimed:         -                  -              1486M (8%)         3531M (19%)            -                  -
[2025-09-24T07:29:50.624+0000][info][gc     ] GC(1) Garbage Collection (Warmup) 3762M(20%)->258M(1%)
[2025-09-24T07:29:52.621+0000][info][gc,heap] GC(2) Min Capacity: 9216M(50%)
[2025-09-24T07:29:52.621+0000][info][gc,heap] GC(2) Max Capacity: 18432M(100%)
[2025-09-24T07:29:52.621+0000][info][gc,heap] GC(2) Soft Max Capacity: 18432M(100%)
[2025-09-24T07:29:52.621+0000][info][gc,heap] GC(2)                Mark Start          Mark End        Relocate Start      Relocate End           High               Low
[2025-09-24T07:29:52.621+0000][info][gc,heap] GC(2)  Capacity:     9216M (50%)        9216M (50%)        9216M (50%)        9216M (50%)        9216M (50%)        9216M (50%)
[2025-09-24T07:29:52.621+0000][info][gc,heap] GC(2)      Free:    12890M (70%)       12868M (70%)       13792M (75%)       18158M (99%)       18158M (99%)       12864M (70%)
[2025-09-24T07:29:52.621+0000][info][gc,heap] GC(2)      Used:     5542M (30%)        5564M (30%)        4640M (25%)         274M (1%)         5568M (30%)         274M (1%)
[2025-09-24T07:29:52.621+0000][info][gc,heap] GC(2)      Live:         -               208M (1%)          208M (1%)          208M (1%)             -                  -
[2025-09-24T07:29:52.621+0000][info][gc,heap] GC(2) Allocated:         -                22M (0%)           26M (0%)           29M (0%)             -                  -
[2025-09-24T07:29:52.621+0000][info][gc,heap] GC(2)   Garbage:         -              5333M (29%)        4405M (24%)          35M (0%)             -                  -
[2025-09-24T07:29:52.621+0000][info][gc,heap] GC(2) Reclaimed:         -                  -               928M (5%)         5297M (29%)            -                  -
[2025-09-24T07:29:52.621+0000][info][gc     ] GC(2) Garbage Collection (Warmup) 5542M(30%)->274M(1%)

Disk Usage Impact:

  • Current: 50 files × 100MB = ~5GB maximum storage
  • New: 10 files × 100MB = ~1GB maximum storage
  • Reduction: 80% less disk usage

Retained Information:

  • GC pause times and duration
  • Heap memory usage before/after GC
  • GC trigger reasons
  • Memory region allocation details

Removed Information:

  • Detailed GC phase timings
  • Worker thread details
  • Metaspace usage (unless critical)
  • Internal GC task information

@halibobo1205 halibobo1205 changed the title feat(jvm): Optimize JVM GC logging for arm64 feat(jvm): optimize JVM GC logging for arm64 Sep 24, 2025
@kuny0707 kuny0707 moved this to In Review in java-tron Sep 25, 2025
@kuny0707 kuny0707 linked an issue Sep 25, 2025 that may be closed by this pull request
17 tasks
@kuny0707 kuny0707 removed type:enhancement minor enhancement topic:log labels Sep 25, 2025
@kuny0707 kuny0707 merged commit b9753ce into tronprotocol:release_v4.8.1 Sep 25, 2025
7 checks passed
@github-project-automation github-project-automation bot moved this from In Review to Done in java-tron Sep 25, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
Status: Done
Development

Successfully merging this pull request may close these issues.

Expand ARM Architecture Compatibility
5 participants