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.
[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.