读取Go gctrace输出

Question

I have gctrace output that looks like this:

gc 6 @48.155s 15%: 0.093+12360+0.32 ms clock, 0.18+7720/21356/3615+0.65 ms cpu, 11039->13278->6876 MB, 14183 MB goal, 8 P

I am not sure how to read the CPU times in particular. I understand that it is broken down into three phases (STW sweep termination, concurrent mark/scan, and STW mark termination), but I'm not sure what the + signs mean (i.e. 0.18+7720 and 3615+0.65). What do these + signs signify?

Answer 1

In your case, they look like assist and termination times;

// CPU time
0.18    : **STW** Sweep termination.
7720ms  : Mark/Scan - Assist Time (GC performed in line with allocation).
21356ms : Mark/Scan - Background GC time.
3615ms  : Mark/Scan - Idle GC time.
0.65ms  : **STW** Mark termination.

I think it changes (or it may) over various Go versions and you can find more detailed info at runtime package docs.

Currently, it is:
    gc # @#s #%: #+#+# ms clock, #+#/#/#+# ms cpu, #->#-># MB, # MB goal, # P
where the fields are as follows:
    gc #        the GC number, incremented at each GC
    @#s         time in seconds since program start
    #%          percentage of time spent in GC since program start
    #+...+#     wall-clock/CPU times for the phases of the GC
    #->#-># MB  heap size at GC start, at GC end, and live heap
    # MB goal   goal heap size
    # P         number of processors used

Example here

See also Interpreting GC trace output

gc 6 @48.155s 15%: 0.093+12360+0.32 ms clock,
0.18+7720/21356/3615+0.65 ms cpu, 11039->13278->6876 MB, 14183 MB goal, 8 P

• gc 6
• @48.155s since program start
• 15%: of time spent in GC since program start
• 0.093+12360+0.32 ms clock stop-the-world (STW) sweep termination + concurrent mark and scan + and STW mark termination
• 0.18+7720/21356/3615+0.65 ms cpu (GC performed in line with allocation), background GC time, and idle GC time
• 11039->13278->6876 MB heap size at GC start, at GC end, and live heap
• 8 P number of processors used