Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

runtime: gc goroutine occasionally use 100% CPU #61046

Open
lixin1234qqq opened this issue Jun 28, 2023 · 3 comments
Open

runtime: gc goroutine occasionally use 100% CPU #61046

lixin1234qqq opened this issue Jun 28, 2023 · 3 comments
Labels
compiler/runtime Issues related to the Go compiler and/or runtime. NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone
Backlog

Comments

@lixin1234qqq
Copy link

lixin1234qqq commented Jun 28, 2023 •
edited
Loading

What version of Go are you using (go version)?

go version 1.19.4
linux
amd64

Does this issue reproduce with the latest release?

not sure

What operating system and processor architecture are you using (go env)?

GOARCH="amd64"
GOOS="linux"

What did you do?

run my application(using cgo) bind to last processor using taskset -c xx
(I'm looking for a way to reproduce this issue stably...)

What did you expect to see?

the cpu usage is stable

What did you see instead?

the cpu usage increased to 100% occasionally sometime
If I a) attached and detached the process using gdb or b) sent SIGSTOP and SIGCONT，the cpu usage was restored

top -Hp pid
one thread used 100% cpu

perf record -F 999 -t tid
result：

44.63%  my-application  [.] runtime.unlock2
37.76%  my-application  [.] runtime.lock2
 6.40%  my-application  [.] runtime.sweepone
 5.02%  my-application  [.] runtime.freeSomeWbufs
 4.91%  my-application  [.] runtime.bgsweep
 0.04%  my-application  [.] runtime.cgoSigtramp.abi0
 0.02%  my-application  [.] runtime.findfunc
 0.01%  my-application  [.] runtime.sigsend
 0.01%  my-application  [.] runtime.findRunnable
 0.01%  my-application  [.] runtime.adjustSignalStack
 0.01%  my-application  [.] runtime.sigfwdgo
 0.01%  my-application  [.] runtime.morestack.abi0
 0.01%  my-application  [.] runtime.doSigPreempt
 0.01%  my-application  [.] runtime.casgstatus
 0.01%  my-application  [.] runtime.isAsyncSafePoint
 0.01%  my-application  [.] runtime.sigtramp.abi0
 0.01%  my-application  [.] runtime.sigtrampgo

Percent│     Disassembly of section .text
       │
       │     000000000083d280 <runtime.bgsweep@@Base>:
       │  0:   cmp    0x10(%r14),%rsp
       │     ↓ jbe    12e
       │       sub    $0x30,%rsp
       │       mov    %rbp,0x28(%rsp
       │       lea    0x28(%rsp),%rbp
       │       mov    %rax,0x20(%rsp
       │       cmpl   $0x0,runtime.writeBarrier@@Base
       │     ↓ jne    32
       │       mov    %r14,%rcx
       │       mov    %rcx,runtime.sweep@@Base+0x8
       │     ↓ jmp    45
       │ 32:   lea    runtime.sweep@@Base+0x8,%rdi
       │       mov    %r14,%rcx
       │       nop
       │     → callq  runtime.gcWriteBarrierCX
       │ 45:   nop
       │       nop
       │       lea    runtime.sweep@@Base,%rax
       │     → callq  runtime.lock2
       │       movb   $0x1,runtime.sweep@@Base+0x10
       │       mov    0x20(%rsp),%rax
       │       lea    go.link.pkghashbytes.vendor/golang.org/x/text/unicode/norm@@Base+0x120,%rbx
       │     → callq  runtime.chansend1
       │       nop
       │       lea    runtime.parkunlock_c·f@@Base,%rax
       │       lea    runtime.sweep@@Base,%rbx
       │       mov    $0xc,%ecx
       │       mov    $0x14,%edi
       │       mov    $0x1,%esi
       │     → callq  runtime.gopark
       │     ↓ jmp    100
       │ 90:   nop
       │       nop
       │       lea    runtime.sweep@@Base,%rax
 15.82 │     → callq  runtime.lock2
  0.10 │       nop
       │       mov    runtime.sweep@@Base+0x1c,%ecx
 17.25 │       cmp    $0x80000000,%ecx
       │     ↓ jne    d9
       │       movb   $0x1,runtime.sweep@@Base+0x
       │       nop
       │       lea    runtime.parkunlock_c·f@@Base,%rax
       │       lea    runtime.sweep@@Base,%rbx
       │       mov    $0xc,%ecx
       │       mov    $0x14,%edi
       │       mov    $0x1,%esi
       │     → callq  runtime.gopark
       │     ↓ jmp    100
       │ d9:   nop
       │       nop
       │       lea    runtime.sweep@@Base,%rax
 17.14 │     → callq  runtime.unlock2
       │     ↓ jmp    100
       │ e9:   incl   runtime.sweep@@Base+0x14
       │       nop
       │       lea    runtime.gosched_m·f@@Base,%rax
       │     → callq  runtime.mcall
       │       nop
 16.74 │100: → callq  runtime.sweepone
       │       cmp    $0xffffffffffffffff,%rax
       │     ↑ jne    e9
       │     ↓ jmp    11a
       │10d:   nop
       │       lea    runtime.gosched_m·f@@Base,%rax
       │     → callq  runtime.mcall
 17.75 │11a:   mov    $0x1,%eax
       │       nop
       │     → callq  runtime.freeSomeWbufs
       │       test   %al,%al
       │     ↑ jne    10d
 15.21 │     ↑ jmpq   90
       │12e:   mov    %rax,0x8(%rsp
       │     → callq  runtime.morestack_noctxt.abi0
       │       mov    0x8(%rsp),%rax
       │       nop
       │       jmpq   0




Percent│     Disassembly of section .text
       │
       │     000000000083d4e0 <runtime.sweepone@@Base>:
 12.27 │  0:   cmp    0x10(%r14),%rsp
       │     ↓ jbe    24c
       │       sub    $0x48,%rsp
       │       mov    %rbp,0x40(%rsp
 13.23 │       lea    0x40(%rsp),%rbp
       │       mov    %r14,0x38(%rsp
       │       mov    0x30(%r14),%rcx
       │       incl   0x108(%rcx
 12.05 │ 27:   nop
       │       mov    runtime.sweep@@Base+0x1c,%eax
 11.58 │       mov    %eax,%ecx
  0.08 │       and    $0x80000000,%eax
       │       test   %eax,%eax
       │     ↓ jne    5c
       │       lea    0x1(%rcx),%edx
       │       mov    %eax,%ebx
       │       mov    %ecx,%eax
       │       lea    runtime.sweep@@Base+0x1c,%rsi
       │       lock   cmpxchg %edx,(%rsi
       │       sete   %cl
       │       test   %cl,%cl
       │     ↑ je     27
       │       mov    runtime.mheap_@@Base+0x10138,%ecx
       │       test   %ebx,%ebx
       │     ↓ jmp    69
       │ 5c:   mov    runtime.mheap_@@Base+0x10138,%ecx
 12.04 │       lea    runtime.sweep@@Base+0x1c,%rsi
       │ 69:   mov    %ecx,0x20(%rsp
       │       sete   0x24(%rsp
 12.45 │     ↓ je     94
  0.16 │       mov    0x38(%rsp),%rcx
       │       mov    0x30(%rcx),%rcx
       │       decl   0x108(%rcx
 13.70 │       mov    $0xffffffffffffffff,%rax
       │       mov    0x40(%rsp),%rbp
 12.44 │       add    $0x48,%rsp
       │     ← retq        
       │ 94:   lea    runtime.mheap_@@Base,%rax
       │       nop
       │     → callq  runtime.(*mheap).nextSpanForSweep
       │       test   %rax,%rax
       │     ↓ je     115
       │       mov    0x63(%rax),%cl
       │       cmp    $0x1,%cl
       │     ↓ je     c9
       │       mov    0x58(%rax),%edx
       │       mov    0x20(%rsp),%ebx
       │       cmp    %edx,%ebx
       │     ↑ je     94
       │       lea    0x3(%rbx),%esi
       │       cmp    %esi,%edx
       │     ↑ je     94
       │     ↓ jmpq   1cd
       │ c9:   mov    %rax,%rbx
       │       lea    0x20(%rsp),%rax
       │     → callq  runtime.(*sweepLocker).tryAcquire
       │       mov    %rax,0x28(%rsp
       │       test   %bl,%bl
       │     ↑ je     94
       │       mov    0x20(%rax),%rcx
       │       mov    %rcx,0x30(%rsp
       │       lea    0x28(%rsp),%rax
       │       xor    %ebx,%ebx
       │     → callq  runtime.(*sweepLocked).sweep
       │       test   %al,%al
       │     ↓ je     10f
       │       nop
       │       mov    0x30(%rsp),%rcx
       │       lea    runtime.mheap_@@Base+0x10188,%rdx
       │       mov    %rcx,%rsi
       │       lock   xadd   %rcx,(%rdx
       │     ↓ jmp    111
       │10f:   xor    %esi,%esi
       │111:   xor    %edx,%edx
       │     ↓ jmp    150    	                              	   
       │115:   nop
       │       mov    runtime.sweep@@Base+0x1c,%eax
       │       mov    %eax,%edx
       │       and    $0x80000000,%eax
       │       test   %eax,%eax
       │     ↓ jne    146
       │       mov    %edx,%esi
       │       bts    $0x1f,%edx
       │       mov    %eax,%ecx
       │       mov    %esi,%eax
       │       lea    runtime.sweep@@Base+0x1c,%rdi
       │       lock   cmpxchg %edx,(%rdi
       │       sete   %dl
       │       nop
       │       test   %dl,%dl
       │     ↑ je     115
       │       test   %ecx,%ecx
       │146:   sete   %dl
       │       mov    $0xffffffffffffffff,%rsi
       │150:   mov    %dl,0x16(%rsp
       │       mov    %rsi,0x30(%rsp
       │       mov    0x20(%rsp),%ebx
       │       movzbl 0x24(%rsp),%ecx
       │       lea    runtime.sweep@@Base+0x1c,%rax
       │     → callq  runtime.(*activeSweep).end
       │       movzbl 0x16(%rsp),%edx
       │       test   %dl,%dl
       │     ↓ je     1af
       │       cmpl   $0x0,runtime.debug@@Base+0x28
       │       xchg   %ax,%ax
       │     ↓ jle    19f
       │       lea    runtime.sweepone.func1·f@@Base,%rax
       │       mov    %rax,(%rsp
       │     → callq  runtime.systemstack.abi0
       │       xorps  %xmm15,%xmm15
       │       mov    %fs:0xfffffffffffffff8,%r14
       │19f:   nop
       │       nop
       │       mov    $0x1,%ecx
       │       lea    runtime.scavenger@@Base+0x20,%rdx
       │       xchg   %ecx,(%rdx)  	 
       │1af:   mov    0x38(%rsp),%rcx
       │       mov    0x30(%rcx),%rcx
       │       decl   0x108(%rcx
       │       mov    0x30(%rsp),%rax
       │       mov    0x40(%rsp),%rbp
       │       add    $0x48,%rsp
       │     ← retq
       │1cd:   mov    %cl,0x17(%rsp
       │       mov    %edx,0x1c(%rsp
       │       mov    %ebx,0x18(%rsp
       │     → callq  runtime.printlock
       │       lea    type.RMd5Pq1o@@Base+0x18daa,%rax
       │       mov    $0x1a,%ebx
       │     → callq  runtime.printstring
       │       movzbl 0x17(%rsp),%eax
       │       movzbl %al,%eax
       │     → callq  runtime.printuint
       │       lea    type.RMd5Pq1o@@Base+0x85f9,%rax
       │       mov    $0xc,%ebx
       │     → callq  runtime.printstring
       │       mov    0x1c(%rsp),%eax
       │     → callq  runtime.printuint
       │       lea    type.RMd5Pq1o@@Base+0x61c5,%rax
       │       mov    $0xa,%ebx
       │     → callq  runtime.printstring
       │       mov    0x18(%rsp),%eax
       │     → callq  runtime.printuint
       │     → callq  runtime.printnl
       │     → callq  runtime.printunlock
       │       lea    type.RMd5Pq1o@@Base+0x1f1d9,%rax
       │       mov    $0x1f,%ebx
       │     → callq  runtime.throw
       │       nop
       │24c: → callq  runtime.morestack_noctxt.abi0
       │     ↑ jmpq   0	     




Percent│    Disassembly of section .text
       │
       │    000000000083f6e0 <runtime.freeSomeWbufs@@Base>:
 16.47 │ 0:   cmp    0x10(%r14),%rsp
       │    ↓ jbe    c3
       │      sub    $0x28,%rsp
       │      mov    %rbp,0x20(%rsp
 11.97 │      lea    0x20(%rsp),%rbp
  6.99 │      mov    %al,0x30(%rsp
       │      nop
       │      lea    runtime.work@@Base+0x50,%rax
 10.88 │    → callq  runtime.lock2
       │      cmpl   $0x0,runtime.gcphase@@Base
 18.66 │    ↓ jne    3c
       │      cmpq   $0x0,runtime.work@@Base+0x58
       │    ↓ jne    56
 18.66 │3c:   nop
       │      nop
       │      lea    runtime.work@@Base+0x50,%rax
       │    → callq  runtime.unlock2
       │      xor    %eax,%eax
       │      mov    0x20(%rsp),%rbp
 16.36 │      add    $0x28,%rsp
       │    ← retq
       │56:   movq   $0x0,0x10(%rsp
       │      movb   $0x0,0x18(%rsp
       │      lea    runtime.freeSomeWbufs.func1@@Base,%rax
       │      mov    %rax,0x10(%rsp
       │      movzbl 0x30(%rsp),%eax
       │      mov    %al,0x18(%rsp
       │      lea    0x10(%rsp),%rax
       │      mov    %rax,(%rsp
       │    → callq  runtime.systemstack.abi0
       │      xorps  %xmm15,%xmm15
       │      mov    %fs:0xfffffffffffffff8,%r14
       │      nop
       │      nop
       │      mov    runtime.work@@Base+0x58,%rax
       │      mov    %rax,0x8(%rsp
       │      lea    runtime.work@@Base+0x50,%rax
       │    → callq  runtime.unlock2
       │      mov    0x8(%rsp),%rax
       │      test   %rax,%rax
       │      setne  %al
       │      mov    0x20(%rsp),%rbp
       │      add    $0x28,%rsp
       │    ← retq
       │c3:   mov    %al,0x8(%rsp
       │    → callq  runtime.morestack_noctxt.abi0
       │      movzbl 0x8(%rsp),%eax
       │    ↑ jmpq   0
@lixin1234qqq lixin1234qqq changed the title affected/package: runtime runtime: gc goroutine occasionally use 100% CPU Jun 28, 2023
@gopherbot gopherbot added the compiler/runtime Issues related to the Go compiler and/or runtime. label Jun 28, 2023
@mknyszek
Copy link
Contributor

Hm, this looks suspiciously like #57523. The fix for that was backported to Go 1.19, but I think the fix is only present in Go 1.19.7 and later. I noticed you're using Go 1.19.4. Can you try Go 1.19.7 and see if you can reproduce?

Thanks!

@mknyszek mknyszek added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Jun 28, 2023
@mknyszek mknyszek added this to the Backlog milestone Jun 28, 2023
@mknyszek mknyszek added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Jun 28, 2023
@lixin1234qqq
Copy link
Author

@mknyszek thx
I will compile my app using go 1.19.7 and check whether a7b7597 has fix this issue in recent days.

I have a question, as mentioned in #57523 , the cpu usage should drop after sweeping, but what i observed was continuously 100%，is this related to taskset -c {last processor id} ?

here is the callchains

-   99.90%     0.00%  my-application  [.] runtime.goexit.abi0
   - runtime.goexit.abi0
      - 99.64% runtime.gcenable.func1
         - 91.54% runtime.bgsweep
            - 40.39% runtime.freeSomeWbufs
                 20.00% runtime.unlock2
                 17.63% runtime.lock2
              22.74% runtime.unlock2
              19.04% runtime.lock2
              4.18% runtime.sweepone
           2.41% runtime.sweepone
           2.23% runtime.freeSomeWbufs
           1.80% runtime.lock2
           1.61% runtime.unlock2

@seankhliao seankhliao added WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. and removed WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. labels Jul 9, 2023
@lixin1234qqq
Copy link
Author

lixin1234qqq commented Jul 30, 2023 •
edited
Loading

Hm, this looks suspiciously like #57523. The fix for that was backported to Go 1.19, but I think the fix is only present in Go 1.19.7 and later. I noticed you're using Go 1.19.4. Can you try Go 1.19.7 and see if you can reproduce?

Thanks!

@mknyszek I reproduce it in go 1.20.5，which shows lower probability, with the same perf record.

only 2 goroutines are running

goroutine 3 [running]:
runtime.unlock2(0x750?)
/go1.20.5/go/src/runtime/lock_futex.go:117 +0x20 fp=0xc00005b750 sp=0xc00005b730 pc=0x4135e0
runtime.unlockWithRank(...)
/go1.20.5/go/src/runtime/lockrank_off.go:32
runtime.unlock(...)
/go1.20.5/go/src/runtime/lock_futex.go:112
runtime.freeSomeWbufs(0x1)
/go1.20.5/go/src/runtime/mgcwork.go:472 +0x4a fp=0xc00005b780 sp=0xc00005b750 pc=0x42ddaa
runtime.bgsweep(0x0?)
/go1.20.5/go/src/runtime/mgcsweep.go:306 +0x167 fp=0xc00005b7c8 sp=0xc00005b780 pc=0x42b987
runtime.gcenable.func1()
/go1.20.5/go/src/runtime/mgc.go:178 +0x26 fp=0xc00005b7e0 sp=0xc00005b7c8 pc=0x420b66
runtime.goexit()
/go1.20.5/go/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc00005b7e8 sp=0xc00005b7e0 pc=0x471261
created by runtime.gcenable
/go1.20.5/go/src/runtime/mgc.go:178 +0x6b

goroutine 23 [running]:
goroutine running on other thread; stack unavailable
created by runtime.gcBgMarkStartWorkers
/go1.20.5/go/src/runtime/mgc.go:1199 +0x25

runtime.forcegchelper() block at semacquire(&gcsema)

goroutine 2 [semacquire]:
runtime.gopark(0xc004d6a0f0?, 0x3?, 0x0?, 0xa3?, 0x20dd5fdcb68819b?)
/go1.20.5/go/src/runtime/proc.go:381 +0xd6 fp=0xc00005aec0 sp=0xc00005aea0 pc=0x440836
runtime.goparkunlock(...)
/go1.20.5/go/src/runtime/proc.go:387
runtime.semacquire1(0x1b9f53c, 0x1?, 0x0, 0x0, 0x0?)
/go1.20.5/go/src/runtime/sema.go:160 +0x20f fp=0xc00005af28 sp=0xc00005aec0 pc=0x451def
runtime.semacquire(...)
/go1.20.5/go/src/runtime/sema.go:111
runtime.gcStart({0x20dd619bdddb09b?, 0x1be1d20?, 0x1411?})
/go1.20.5/go/src/runtime/mgc.go:626 +0x159 fp=0xc00005afb0 sp=0xc00005af28 pc=0x4210d9
runtime.forcegchelper()
/go1.20.5/go/src/runtime/proc.go:311 +0x65 fp=0xc00005afe0 sp=0xc00005afb0 pc=0x440625
runtime.goexit()
/go1.20.5/go/src/runtime/asm_amd64.s:1598 +0x1 fp=0xc00005afe8 sp=0xc00005afe0 pc=0x471261
created by runtime.init.6
/go1.20.5/go/src/runtime/proc.go:293 +0x25

many goroutines block at semacquire(&work.startSema)
goroutine 44 [semacquire]:
runtime.gopark(0xc0023a0b80?, 0x428c85?, 0x60?, 0x3d?, 0x0?)
/go1.20.5/go/src/runtime/proc.go:381 +0xd6 fp=0xc0023a0b40 sp=0xc0023a0b20 pc=0x440836
runtime.goparkunlock(...)
/go1.20.5/go/src/runtime/proc.go:387
runtime.semacquire1(0x1be39b8, 0x47?, 0x0, 0x0, 0x8?)
/go1.20.5/go/src/runtime/sema.go:160 +0x20f fp=0xc0023a0ba8 sp=0xc0023a0b40 pc=0x451def
runtime.semacquire(...)
/go1.20.5/go/src/runtime/sema.go:111
runtime.gcStart({0x7ff8c3b1af18?, 0xc0023a0c0d?, 0x23a0c78?})
/go1.20.5/go/src/runtime/mgc.go:607 +0xf5 fp=0xc0023a0c30 sp=0xc0023a0ba8 pc=0x421075
runtime.mallocgc(0x32, 0x0, 0x0)
/go1.20.5/go/src/runtime/malloc.go:1172 +0x777 fp=0xc0023a0c98 sp=0xc0023a0c30 pc=0x415137
runtime.rawstring(...)
/go1.20.5/go/src/runtime/string.go:267
runtime.rawstringtmp(0xa74900?, 0x32)
/go1.20.5/go/src/runtime/string.go:131 +0x46 fp=0xc0023a0cc0 sp=0xc0023a0c98 pc=0x459f46
runtime.concatstrings(0xfeae20?, {0xc0023a0d50?, 0x5, 0x7ff8c3b1af18?})
/go1.20.5/go/src/runtime/string.go:51 +0xe9 fp=0xc0023a0d30 sp=0xc0023a0cc0 pc=0x4598e9
runtime.concatstring5(0xc0018af6f8?, {0x107cd3e?, 0x1b9fa18?}, {0x119d228?, 0xc0018af6c0?}, {0xc0025910b0?, 0x539d34?}, {0x107ba8c?, 0x11?}, {0x10909e4, ...})
/go1.20.5/go/src/runtime/string.go:72 +0xab fp=0xc0023a0db0 sp=0xc0023a0d30 pc=0x459d6b

@seankhliao seankhliao removed the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Sep 10, 2023
@gabyhelp gabyhelp mentioned this issue Jul 16, 2024
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
compiler/runtime Issues related to the Go compiler and/or runtime. NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
Go Compiler / Runtime
Status: Todo
Milestone
Backlog
Development

No branches or pull requests
4 participants
@mknyszek @gopherbot @seankhliao @lixin1234qqq