Uploaded image for project: 'JDK'
  1. JDK
  2. JDK-8165292

The gc+task logging is repeated a lot, decreasing the usefulness of -Xlog:gc*=info

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Fixed
    • Icon: P2 P2
    • 9
    • 9
    • hotspot
    • gc
    • b137
    • Verified

      The logging on gc,task is repeated a lot, see the following example:

      [24.798s][info][gc ] GC(14) Pause Young (G1 Evacuation Pause) 1349M->74M(4776M) (24.173s, 24.798s) 625.258ms
      [24.798s][info][gc,cpu ] GC(14) User=2.35s Sys=0.33s Real=0.63s
      [26.584s][info][gc,start ] GC(15) Pause Young (G1 Evacuation Pause) (26.584s)
      [26.584s][info][gc,task ] GC(15) GC Workers: using 18 out of 18
      [26.585s][info][gc,task ] GC(15) GC Workers: using 18 out of 18
      [26.632s][info][gc,task ] GC(15) GC Workers: using 18 out of 18
      [26.680s][info][gc,task ] GC(15) GC Workers: using 2 out of 18
      [26.680s][info][gc,task ] GC(15) GC Workers: using 18 out of 18
      [26.683s][info][gc,task ] GC(15) GC Workers: using 18 out of 18
      [26.683s][info][gc,task ] GC(15) GC Workers: using 18 out of 18
      [26.683s][info][gc,task ] GC(15) GC Workers: using 15 out of 18
      [26.866s][info][gc,task ] GC(15) GC Workers: using 18 out of 18

      This is because AbstractWorkGang::update_active_workers *always* logs on the tags gc and task on info level. How often is AbstractWorkGang::update_active_workers called? Twice for every time WorkGang::run_task is called, resulting a lot of additional logging.

      The bug is worse because a user can no longer enable the info level for all tags with gc by using -Xlog:gc*=info, since the output becomes too large.

      The bug is reproducible by running e.g. GCBasher with -Xlog:gc*=info.

            tschatzl Thomas Schatzl
            ehelin Erik Helin
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

              Created:
              Updated:
              Resolved: