profile was collecting within 120s, but Total samples is 29838s

[fubss]

Hello!

Could you help me to explain it, please?

What may be a reason of it? Is it commonly happens with fgprof or it is just my weird case?

What did I do:

1) I added the module and code from README to my app source code:

    // Start profiling http endpoint if enabled
    if profileEnabled {
        http.DefaultServeMux.Handle("/debug/fgprof", fgprof.Handler()) // I've added this line to the existing part of code
        go func() {
            logger.Infof("Starting profiling server with listenAddress = %s", profileListenAddress)
            if profileErr := http.ListenAndServe(profileListenAddress, nil); profileErr != nil {
                logger.Errorf("Error starting profiler: %s", profileErr)
            }
        }()
    }

2) I ran my application which consists of 5 different docker containers. 3) I ran command go tool pprof http://localhost:6060/debug/pprof/goroutine?seconds=120 4) I downloaded profiling files to my client machine from the host. 5) I ran command go tool pprof -http :9098 pprof.samples.time.005.pb.gz and saw weird "Total samples" time for this profile:

Type: time
Time: Sep 29, 2022 at 10:16am (MSK)
Duration: 120s, Total samples = 29838.05s (24864.86%)
Showing nodes accounting for 29838.05s, 100% of 29838.05s total
See https://git.io/JfYMW for how to read the graph

lscpu

Architecture: x86_64 CPU op-mode(s): 32-bit, 64-bit Byte Order: Little Endian Address sizes: 40 bits physical, 57 bits virtual CPU(s): 4 On-line CPU(s) list: 0-3 Thread(s) per core: 2 Core(s) per socket: 2 Socket(s): 1 NUMA node(s): 1 Vendor ID: GenuineIntel CPU family: 6 Model: 106 Model name: Intel Xeon Processor (Icelake) Stepping: 0 CPU MHz: 1999.990 BogoMIPS: 3999.98 Hypervisor vendor: KVM Virtualization type: full L1d cache: 64 KiB L1i cache: 64 KiB L2 cache: 8 MiB L3 cache: 16 MiB NUMA node0 CPU(s): 0-3 Vulnerability Itlb multihit: Not affected Vulnerability L1tf: Not affected Vulnerability Mds: Not affected Vulnerability Meltdown: Not affected Vulnerability Mmio stale data: Not affected Vulnerability Spec store bypass: Mitigation; Speculative Store Bypass disabled via prctl and seccomp Vulnerability Spectre v1: Mitigation; usercopy/swapgs barriers and __user pointer sanitization Vulnerability Spectre v2: Mitigation; Enhanced IBRS, IBPB conditional, RSB filling Vulnerability Srbds: Not affected Vulnerability Tsx async abort: Not affected Flags: fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ht syscall nx pdpe1gb rdtscp lm constant_t sc rep_good nopl xtopology nonstop_tsc cpuid tsc_known_freq pni pclmulqdq ssse3 fma cx16 pcid sse4_1 sse4_2 x2apic movbe popcnt tsc_deadline _timer aes xsave avx f16c rdrand hypervisor lahf_lm abm 3dnowprefetch cpuid_fault invpcid_single ssbd ibrs ibpb stibp ibrs_enhanced fsgsbase bmi1 avx2 smep bmi2 erms invpcid avx512f avx512dq rdseed adx smap avx512ifma clflushopt clwb avx512cd sha_ni avx512bw avx512vl xsaveopt xsa vec xgetbv1 arat avx512vbmi umip pku ospke avx512_vbmi2 gfni vaes vpclmulqdq avx512_vnni avx512_bitalg avx512_vpopcntdq md_clear arch_capabi lities

go env

GO111MODULE="" GOARCH="amd64" GOBIN="" GOCACHE="/home/ivanl/.cache/go-build" GOENV="/home/ivanl/.config/go/env" GOEXE="" GOEXPERIMENT="" GOFLAGS="" GOHOSTARCH="amd64" GOHOSTOS="linux" GOINSECURE="" GOMODCACHE="/home/ivanl/go/pkg/mod" GONOPROXY="" GONOSUMDB="" GOOS="linux" GOPATH="/home/ivanl/go" GOPRIVATE="" GOPROXY="https://proxy.golang.org,direct" GOROOT="/usr/local/go" GOSUMDB="sum.golang.org" GOTMPDIR="" GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64" GOVCS="" GOVERSION="go1.18.4" GCCGO="gccgo" GOAMD64="v1" AR="ar" CC="gcc" CXX="g++" CGO_ENABLED="1" GOMOD="/dev/null" GOWORK="" CGO_CFLAGS="-g -O2" CGO_CPPFLAGS="" CGO_CXXFLAGS="-g -O2" CGO_FFLAGS="-g -O2" CGO_LDFLAGS="-g -O2" PKG_CONFIG="pkg-config" GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build2800466746=/tmp/go-build -gno-record-gcc-switches"

docker images' go-version: 1.16.7

[felixge]

Yes, this is normal. The way you can think of it is that the time of all goroutines is captured. If you have 2 goroutines and profile them for 120s, then 120s will have passed for each, resulting in a total of 240s.

In your case it seems like your program was running an average of ~250 goroutines (29838/120).

If you'd like to break down the time of each goroutine individually, I'd suggest to take a look at https://github.com/felixge/fgtrace.

I'm closing this for but, but please let me know if this makes sense.

[fubss]

Thank you!