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.

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

std/channels is slower than system/channels_builtin or hangs (EDIT: gives EXC_BAD_ACCESS) #17392

Closed
timotheecour opened this issue Mar 16, 2021 · 16 comments

Comments

@timotheecour
Copy link
Member

timotheecour commented Mar 16, 2021

Example

adapted from benchmark from nim-lang/website#274 (found while attempting to improve the example in nim-lang/website#274)

when true: # D20210316T000718
  import std/times
  when defined(newChan):
    import std/[channels, isolation]
  var
    sender: array[15, Thread[void]]
    receiver: array[15, Thread[void]]
  let maxItems = 1000

  const sentinel = @["end"] # xxx maybe also show a solution with `Atomic` or mutex
  proc getPayload(): string =
    for i in 0..<10:
      result.add $i
  const payload = getPayload()
  
  when defined(newChan):
    var chan = newChannel[seq[string]](maxItems)
    proc recvHandler() =
      var x: seq[string]
      while true:
        chan.recv(x) # xxx we could remove duplication if channels_builtin supported this
        if x == sentinel: break
  elif defined(oldChan):
    var chan: Channel[seq[string]]
    chan.open(maxItems = maxItems)
    proc recvHandler() =
      var x: seq[string]
      while true:
        x = chan.recv()
        if x == sentinel: break
  else: static: doAssert false

  let n = 1000
  proc sendHandler() =
    for i in 0..<n:
      chan.send(@[payload])
    chan.send(sentinel)

  var tot = 0.0
  proc benchmark() =
    for t in mitems(sender):
      t.createThread(sendHandler)
    for t in mitems(receiver):
      t.createThread(recvHandler)
    let t = epochTime()
    joinThreads(sender)
    joinThreads(receiver)
    let t2 = epochTime()
    tot += t2 - t

  for i in 0..100:
    benchmark()
  echo tot

Current Output

nim c --threads --gc:arc --lib:lib -d:oldChan -d:danger -o:/tmp/z01 main.nim
nim c --threads --gc:arc --lib:lib -d:newChan -d:danger -o:/tmp/z02 main.nim

for i in {1..2000}; do /tmp/z01 ; done
0.5778560638427734
0.4162607192993164
0.4190213680267334
0.6117517948150635
0.4808053970336914
0.4466562271118164
0.4234135150909424
etc... (doesn't hang)

for i in {1..2000}; do /tmp/z02 ; done
1.274321317672729
1.335514068603516
1.379576206207275
1.460080862045288
1.465322256088257
1.588825702667236
1.528374195098877
1.564008951187134
1.734921455383301
1.611903429031372
1.667627096176147
(hangs here...)

  • -d:newChan is 4x slower than -d:oldChan in this example
  • -d:newChan hangs but -d:oldChan does not hang
  • this holds true with 10x bigger or 10x smaller maxItems

note 1

some debug info for the hang:

ps auwx| grep /tmp/z02
lldb -p 68230
command script list
Current user-defined commands:
  d_help      -- For more information run 'help d_help'
  d_reimport  -- For more information run 'help d_reimport'
  d_rerun_fun -- For more information run 'help d_rerun_fun'
For more information on any command, type 'help <command-name>'.
(lldb) process attach --pid 68230
Process 68230 stopped
* thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
    frame #0: 0x00007fff6a66955e libsystem_kernel.dylib`__ulock_wait + 10
libsystem_kernel.dylib`__ulock_wait:
->  0x7fff6a66955e <+10>: jae    0x7fff6a669568            ; <+20>
    0x7fff6a669560 <+12>: movq   %rax, %rdi
    0x7fff6a669563 <+15>: jmp    0x7fff6a668629            ; cerror_nocancel
    0x7fff6a669568 <+20>: retq
Target 0: (z02) stopped.

Executable module set to "/tmp/z02".
Architecture set to: x86_64h-apple-macosx-.
(lldb) bt
* thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
  frame #0: 0x00007fff6a66955e libsystem_kernel.dylib`__ulock_wait + 10
  frame #1: 0x00007fff6a72c5c2 libsystem_pthread.dylib`_pthread_join + 347
  frame #2: 0x00000001064d6dba z02`joinThreads__EUhnNwjGgP1T7DXjHjum7A + 42
  frame #3: 0x00000001064d81c5 z02`benchmark__zybol9an1ajv6WvIcP5tJgA + 293
  frame #4: 0x00000001064d82bc z02`NimMainModule + 92
  frame #5: 0x00000001064d83d8 z02`main + 72
  frame #6: 0x00007fff6a526cc9 libdyld.dylib`start + 1
(lldb)

note 2

probably not related to the performance difference or the hang of std/channels, but where are resources deallocated for createThread ?
all I see is a disabled proc with an suspicious comment:

when false:
  # XXX a thread should really release its heap here somehow:
  proc destroyThread*[TArg](t: var Thread[TArg]) =

Additional Information

1.5.1 d5eb658

@ringabout
Copy link
Member

ringabout commented Mar 16, 2021

when true: # D20210316T000718
  import std/times
  when defined(newChan):
    import std/channels
    import std/[isolation]
  var
    sender: array[15, Thread[void]]
    receiver: array[15, Thread[void]]
  let maxItems = 1000

  const sentinel = @["end"] # xxx maybe also show a solution with `Atomic` or mutex
  proc getPayload(): string =
    for i in 0..<10:
      result.add $i
  const payload = getPayload()
  
  when defined(newChan):
    var chan = newChannel[seq[string]](maxItems)
    proc recvHandler() =
      var x: Isolated[seq[string]]
      while true:
        x = chan.recvIso()
        if x.extract == sentinel: break
  elif defined(oldChan):
    import std/[isolation]
    var chan: Channel[seq[string]]
    chan.open(maxItems = maxItems)
    proc recvHandler() =
      var x: Isolated[seq[string]]
      while true:
        x = isolate(chan.recv())
        if x.extract == sentinel: break
  else: static: doAssert false

  let n = 1000
  proc sendHandler() =
    for i in 0..<n:
      chan.send(@[payload])
    chan.send(sentinel)

  var tot = 0.0
  proc benchmark() =
    for t in mitems(sender):
      t.createThread(sendHandler)
    for t in mitems(receiver):
      t.createThread(recvHandler)

    let t = epochTime()
    joinThreads(sender)
    joinThreads(receiver)
    let t2 = epochTime()
    tot += t2 - t

  for i in 0..100:
    benchmark()
  echo tot

Old channels also leak.

@ringabout

This comment has been minimized.

@timotheecour
Copy link
Member Author

timotheecour commented Mar 17, 2021

Edited:

[First example]
(EDIT: this one now doesn't hang anymore after #17717)
revised and improved example now that #17394 was merged:

when defined case10a2: # D20210317T164951:here gitissue
  import std/times
  when defined(newChan):
    import std/[channels, isolation]
  var
    sender: array[15, Thread[void]]
    receiver: array[15, Thread[void]]
  let maxItems = 100
  const sentinel = @["end"]
  const payload = newString(5000)
  
  when defined(newChan):
    var chan = newChannel[seq[string]](maxItems)
    proc recvHandler() =
      while true:
        let x = chan.recv()
        if x == sentinel: break
  elif defined(oldChan):
    var chan: Channel[seq[string]]
    chan.open(maxItems = maxItems)
    proc recvHandler() =
      var x: seq[string]
      while true:
        x = chan.recv()
        if x == sentinel: break
  else: static: doAssert false

  let n = 30
  proc sendHandler() =
    for i in 0..<n:
      chan.send(@[payload])
    chan.send(sentinel)

  var tot = 0.0
  proc benchmark() =
    for t in mitems(sender):
      t.createThread(sendHandler)
    for t in mitems(receiver):
      t.createThread(recvHandler)
    let t = epochTime()
    joinThreads(sender)
    joinThreads(receiver)
    let t2 = epochTime()
    tot += t2 - t

  for i in 0..100:
    benchmark()
  echo tot

nim c --threads -d:newChan --gc:arc -d:danger -d:case10a2 -o:/tmp/z010a2 -g $timn_D/tests/nim/all/t12015.nim
nim c --threads -d:oldChan --gc:arc -d:danger -d:case10a2 -o:/tmp/z010a2o -g $timn_D/tests/nim/all/t12015.nim

for i in {1..200}; do /tmp/z010a2 ; done
hangs in < 10 seconds
for i in {1..200}; do /tmp/z010a2o ; done
does not hang

bt for all threads: (previously i was only showing main thread, but now using bt all)
=> shows it blocks in recvMpmc__W8ZwIOJ3xUtwXFB9b9brnXGg_3 > _pthread_cond_wait > __psynch_cvwait

(lldb) process attach --pid 91804
Process 91804 stopped
* thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
    frame #0: 0x00007fff6a66955e libsystem_kernel.dylib`__ulock_wait + 10
libsystem_kernel.dylib`__ulock_wait:
->  0x7fff6a66955e <+10>: jae    0x7fff6a669568            ; <+20>
    0x7fff6a669560 <+12>: movq   %rax, %rdi
    0x7fff6a669563 <+15>: jmp    0x7fff6a668629            ; cerror_nocancel
    0x7fff6a669568 <+20>: retq
Target 0: (z010a) stopped.

Executable module set to "/tmp/z010a".
Architecture set to: x86_64h-apple-macosx-.
(lldb) bt all
* thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
  frame #0: 0x00007fff6a66955e libsystem_kernel.dylib`__ulock_wait + 10
  frame #1: 0x00007fff6a72c5c2 libsystem_pthread.dylib`_pthread_join + 347
    frame #2: 0x00000001035d527a start-addr:0x00000001035d5273  z010a joinThreads__EUhnNwjGgP1T7DXjHjum7A [inlined] joinThread__7D7AwDmpXtzT3oBp9c4SUzwsystem(t=<unavailable>) + 42 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system/threads.nim:235:22
    frame #3: 0x00000001035d5273 start-addr:0x00000001035d5273  z010a joinThreads__EUhnNwjGgP1T7DXjHjum7A(t=<unavailable>, tLen_0=<unavailable>) + 35
    frame #4: 0x00000001035d6685 start-addr:0x00000001035d6674  z010a benchmark__zybol9an1ajv6WvIcP5tJgA + 293 at  /Users/timothee/git_clone/nim/timn/tests/nim/all/t12015.nim:646:2
    frame #5: 0x00000001035d677c start-addr:0x00000001035d6777  z010a NimMainModule + 92 at  /Users/timothee/git_clone/nim/timn/tests/nim/all/t12015.nim:652:5
    frame #6: 0x00000001035d6898 start-addr:0x00000001035d6896  z010a main [inlined] NimMain + 72 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system.nim:2217:2
    frame #7: 0x00000001035d686c start-addr:0x00000001035d686c  z010a main(argc=<unavailable>, args=<unavailable>, env=<unavailable>) + 28
  frame #8: 0x00007fff6a526cc9 libdyld.dylib`start + 1
  thread #2
    frame #0: 0x00007fff6a66a882 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff6a72b425 libsystem_pthread.dylib`_pthread_cond_wait + 698
    frame #2: 0x00000001035d615b start-addr:0x00000001035d6150  z010a recvMpmc__W8ZwIOJ3xUtwXFB9b9brnXGg_3 [inlined] wait__AelMZFoEpIv2zok9a8VBM3glocks(cond=0x00007fc0184059d0, lock=<unavailable>) + 203 at  /Users/timothee/git_clone/nim/Nim_devel/lib/core/locks.nim:65:2
    frame #3: 0x00000001035d6150 start-addr:0x00000001035d6150  z010a recvMpmc__W8ZwIOJ3xUtwXFB9b9brnXGg_3(chan=0x00007fc018405920, data=0x000070000629bf20, size=16, nonBlocking=<unavailable>) + 192
    frame #4: 0x00000001035d650d start-addr:0x00000001035d64fe  z010a recvHandler__zybol9an1ajv6WvIcP5tJgA_3 [inlined] recv__JOmg2lX4KXKV9abUuxyXdCQchannels(c=<unavailable>) + 22 at  /Users/timothee/git_clone/nim/Nim_devel/lib/std/channels.nim:482:27
    frame #5: 0x00000001035d64f7 start-addr:0x00000001035d64f7  z010a recvHandler__zybol9an1ajv6WvIcP5tJgA_3 + 55
    frame #6: 0x00000001035d47cd start-addr:0x00000001035d47ca  z010a threadProcWrapDispatch__Mxf9cF7DzrT73i52k5zPHQA_2(thrd=<unavailable>) + 13 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system/threads.nim:141:2
    frame #7: 0x00000001035d4982 start-addr:0x00000001035d497d  z010a threadProcWrapper__KwtUyNVh00QDWGRZcngjGA [inlined] threadProcWrapStackFrame__Mxf9cF7DzrT73i52k5zPHQA(thrd=0x00000001035e1b80) + 18 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system/threads.nim:167:2
    frame #8: 0x00000001035d497d start-addr:0x00000001035d497d  z010a threadProcWrapper__KwtUyNVh00QDWGRZcngjGA(closure=0x00000001035e1b80) + 13
    frame #9: 0x00007fff6a72b109 libsystem_pthread.dylib`_pthread_start + 148
    frame #10: 0x00007fff6a726b8b libsystem_pthread.dylib`thread_start + 15

@timotheecour
Copy link
Member Author

timotheecour commented Mar 18, 2021

Edited:

[Second example]

and in this example, contrary to previous one, the hang happens with both oldChan and newChan;

when defined case10c: # D20210317T170408
#[
nim r --threads -d:newChan --gc:arc -d:danger -d:case10c -o:/tmp/z010c2 -g $timn_D/tests/nim/all/t12015.nim
]#
  import std/times
  when defined(newChan):
    import std/[channels, isolation]
  var
    sender: array[15, Thread[void]]
    receiver: array[15, Thread[void]]
  let maxItems = 3
  const sentinel = @["end"] # xxx maybe also show a solution with `Atomic` or mutex
  const payload = newString(5000)
  
  when defined(newChan):
    var chan = newChannel[seq[string]](maxItems)
    proc recvHandler() =
      var x: seq[string]
      while true:
        x = chan.recv()
        if x == sentinel: break
  elif defined(oldChan):
    var chan: Channel[seq[string]]
    chan.open(maxItems = maxItems)
    proc recvHandler() =
      var x: seq[string]
      while true:
        x = chan.recv()
        if x == sentinel: break
  else: static: doAssert false

  let n = 10
  proc sendHandler() =
    for i in 0..<n:
      chan.send(@[payload])
    chan.send(sentinel)

  var tot = 0.0
  proc benchmark() =
    for t in mitems(sender):
      t.createThread(sendHandler)
    for t in mitems(receiver):
      t.createThread(recvHandler)
    let t = epochTime()
    joinThreads(sender)
    joinThreads(receiver)
    let t2 = epochTime()
    tot += t2 - t

  for i in 0..5000:
    echo i
    benchmark()
  echo tot

it's simpler to reproduce the bug in this case:

nim r --threads -d:oldChan --gc:arc -d:danger -d:case10c -g $timn_D/tests/nim/all/t12015.nim
hangs in < 10 seconds
lldb bt all: see https://gist.github.com/timotheecour/23ba7f8cafac1c5657463d239db2f577

nim r --threads -d:newChan --gc:arc -d:danger -d:case10c -g $timn_D/tests/nim/all/t12015.nim
hangs in < 10 seconds
lldb bt all:

(lldb) process attach --pid 95969
Process 95969 stopped
* thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
    frame #0: 0x00007fff6a66955e libsystem_kernel.dylib`__ulock_wait + 10
libsystem_kernel.dylib`__ulock_wait:
->  0x7fff6a66955e <+10>: jae    0x7fff6a669568            ; <+20>
    0x7fff6a669560 <+12>: movq   %rax, %rdi
    0x7fff6a669563 <+15>: jmp    0x7fff6a668629            ; cerror_nocancel
    0x7fff6a669568 <+20>: retq
Target 0: (t12015) stopped.

Executable module set to "/Users/timothee/git_clone/nim/timn/build/nimcache/t12015".
Architecture set to: x86_64h-apple-macosx-.
(lldb) bt all
* thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
  frame #0: 0x00007fff6a66955e libsystem_kernel.dylib`__ulock_wait + 10
  frame #1: 0x00007fff6a72c5c2 libsystem_pthread.dylib`_pthread_join + 347
    frame #2: 0x0000000109ed5a8a start-addr:0x0000000109ed5a83  t12015 joinThreads__EUhnNwjGgP1T7DXjHjum7A [inlined] joinThread__7D7AwDmpXtzT3oBp9c4SUzwsystem(t=<unavailable>) + 42 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system/threads.nim:235:22
    frame #3: 0x0000000109ed5a83 start-addr:0x0000000109ed5a83  t12015 joinThreads__EUhnNwjGgP1T7DXjHjum7A(t=<unavailable>, tLen_0=<unavailable>) + 35
    frame #4: 0x0000000109ed6de5 start-addr:0x0000000109ed6dd4  t12015 benchmark__zybol9an1ajv6WvIcP5tJgA + 293 at  /Users/timothee/git_clone/nim/timn/tests/nim/all/t12015.nim:809:2
    frame #5: 0x0000000109ed6f29 start-addr:0x0000000109ed6f24  t12015 NimMainModule + 169 at  /Users/timothee/git_clone/nim/timn/tests/nim/all/t12015.nim:815:5
    frame #6: 0x0000000109ed7058 start-addr:0x0000000109ed7056  t12015 main [inlined] NimMain + 72 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system.nim:2217:2
    frame #7: 0x0000000109ed702c start-addr:0x0000000109ed702c  t12015 main(argc=<unavailable>, args=<unavailable>, env=<unavailable>) + 28
  frame #8: 0x00007fff6a526cc9 libdyld.dylib`start + 1
  frame #9: 0x00007fff6a526cc9 libdyld.dylib`start + 1
  thread #2
    frame #0: 0x00007fff6a66a882 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff6a72b425 libsystem_pthread.dylib`_pthread_cond_wait + 698
    frame #2: 0x0000000109ed68bb start-addr:0x0000000109ed68b0  t12015 recvMpmc__W8ZwIOJ3xUtwXFB9b9brnXGg_3 [inlined] wait__AelMZFoEpIv2zok9a8VBM3glocks(cond=0x00007fb3ad4059d0, lock=<unavailable>) + 203 at  /Users/timothee/git_clone/nim/Nim_devel/lib/core/locks.nim:65:2
    frame #3: 0x0000000109ed68b0 start-addr:0x0000000109ed68b0  t12015 recvMpmc__W8ZwIOJ3xUtwXFB9b9brnXGg_3(chan=0x00007fb3ad405920, data=0x000070000735ff20, size=16, nonBlocking=<unavailable>) + 192
    frame #4: 0x0000000109ed6c6d start-addr:0x0000000109ed6c5e  t12015 recvHandler__zybol9an1ajv6WvIcP5tJgA_3 [inlined] recv__JOmg2lX4KXKV9abUuxyXdCQchannels(c=<unavailable>) + 22 at  /Users/timothee/git_clone/nim/Nim_devel/lib/std/channels.nim:482:27
    frame #5: 0x0000000109ed6c57 start-addr:0x0000000109ed6c57  t12015 recvHandler__zybol9an1ajv6WvIcP5tJgA_3 + 55
    frame #6: 0x0000000109ed4fdd start-addr:0x0000000109ed4fda  t12015 threadProcWrapDispatch__Mxf9cF7DzrT73i52k5zPHQA_2(thrd=<unavailable>) + 13 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system/threads.nim:141:2
    frame #7: 0x0000000109ed5192 start-addr:0x0000000109ed518d  t12015 threadProcWrapper__KwtUyNVh00QDWGRZcngjGA [inlined] threadProcWrapStackFrame__Mxf9cF7DzrT73i52k5zPHQA(thrd=0x0000000109ee2bb0) + 18 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system/threads.nim:167:2
    frame #8: 0x0000000109ed518d start-addr:0x0000000109ed518d  t12015 threadProcWrapper__KwtUyNVh00QDWGRZcngjGA(closure=0x0000000109ee2bb0) + 13
    frame #9: 0x00007fff6a72b109 libsystem_pthread.dylib`_pthread_start + 148
    frame #10: 0x00007fff6a726b8b libsystem_pthread.dylib`thread_start + 15

(EDIT) without -d:danger

this is more informative as to explaining the deadlock:
nim r --threads -d:newChan --gc:arc -d:case10c -g $timn_D/tests/nim/all/t12015.nim
hangs in < 10s
lldb bt all:
https://gist.github.com/timotheecour/bedd47e519d6c07a9d449e619ba1b775

it shows 2 interesting things:

    frame #5: 0x000000010f0fd38e start-addr:0x000000010f0fd389  t12015 rawNewString(space=2000) + 238 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system/strs_v2.nim:111:26
    frame #6: 0x000000010f10209e start-addr:0x000000010f102094  t12015 signalHandler(sign=11) + 46 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system/excpt.nim:629:8
    frame #7: 0x00007fff6a71f5fd libsystem_platform.dylib`_sigtramp + 29
    frame #8: 0x000000010f0f9d3c start-addr:0x000000010f0f9d3b  t12015 del__Io5JDKCS5u26IEWw0J53hQ(a=0x000000010f113018, t=0x000000010f1158c0, x=4548026400) + 92 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system/avltree.nim:74:9
    frame #9: 0x000000010f0fa858 start-addr:0x000000010f0fa84d  t12015 rawDealloc__K7uQ6aTKvW6OnOV8EMoNNQ(a=0x000000010f113018, p=0x000000010f1560c0) + 856 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system/alloc.nim:871:3

@timotheecour
Copy link
Member Author

timotheecour commented Mar 18, 2021

here's more info (see above for code #17392 (comment))

nim -v: 4bfc5a9

nim c --threads -d:newChan --stacktrace:off --gc:arc -d:case10c -g $timn_D/tests/nim/all/t12015.nim
(ditto with orc)

lldb -o run /Users/timothee/git_clone/nim/timn/tests/nim/all/t12015
depending on the runs, there is a crash in 1 of 2 places:

Process 37573 stopped
* thread #15, stop reason = EXC_BAD_ACCESS (code=1, address=0x0)
    frame #0: 0x00000001000047fb start-addr:0x00000001000047fb  t12015 del__Io5JDKCS5u26IEWw0J53hQ(a=0x0000000100017018, t=0x00000001000198c0, x=4296405024) + 27 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system/avltree.nim:74:9
   71       split(t)
   72
   73   proc del(a: var MemRegion, t: var PAvlNode, x: int) {.benign.} =
-> 74     if isBottom(t): return
   75     a.last = t
   76     if x <% t.key:
   77       del(a, t.link[0], x)
Target 0: (t12015) stopped.
(lldb) bt
* thread #15, stop reason = EXC_BAD_ACCESS (code=1, address=0x0)
  * frame #0: 0x00000001000047fb start-addr:0x00000001000047fb  t12015 del__Io5JDKCS5u26IEWw0J53hQ(a=0x0000000100017018, t=0x00000001000198c0, x=4296405024) + 27 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system/avltree.nim:74:9
    frame #1: 0x0000000100004e2c start-addr:0x0000000100004e21  t12015 rawDealloc__K7uQ6aTKvW6OnOV8EMoNNQ(a=0x0000000100017018, p=0x000000010015f160) + 492 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system/alloc.nim:871:3
    frame #2: 0x0000000100004ebd start-addr:0x0000000100004eb8  t12015 dealloc__Jg1OaY9ahkT3MBopLAXRSGw(allocator=0x0000000100017018, p=0x000000010015f160) + 29 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system/alloc.nim:972:2
    frame #3: 0x0000000100004efb start-addr:0x0000000100004eec  t12015 deallocSharedImpl__SAtZpVrJ3o5FJvSdLQe9auA(p=0x000000010015f160) + 43 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system/alloc.nim:1087:2
    frame #4: 0x0000000100004f25 start-addr:0x0000000100004f20  t12015 deallocShared(p=0x000000010015f160) + 21 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system/memalloc.nim:308:2
    frame #5: 0x0000000100004f59 start-addr:0x0000000100004f54  t12015 alignedDealloc(p=0x000000010015f160, align=8) + 41 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system/memalloc.nim:367:3
    frame #6: 0x0000000100009f09 start-addr:0x0000000100009efc  t12015 eqdestroy___0RiuPw9cXhtLB9a2rQ2jA69cg(dest=0x000070000f1d8f00) + 169 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system.nim:2247:58
    frame #7: 0x000000010000a2ef start-addr:0x000000010000a2ea  t12015 eqsink___r6aagoRVuov7HvfEjIi3Uw_2(dest=0x000070000f1d8f00, src=tySequence__sM4lkSb7zS6F7OVMvW9cffQ @ 0x000070000f1d8eb0) + 47 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system.nim:2247:2
    frame #8: 0x000000010000d3a8 start-addr:0x000000010000d397  t12015 recvHandler__zybol9an1ajv6WvIcP5tJgA_3 + 120 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system.nim:2247:4
    frame #9: 0x000000010000993c start-addr:0x0000000100009939  t12015 threadProcWrapDispatch__Mxf9cF7DzrT73i52k5zPHQA_2(thrd=0x0000000100019b40) + 28 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system/threads.nim:141:2
    frame #10: 0x0000000100009ac5 start-addr:0x0000000100009ac0  t12015 threadProcWrapStackFrame__Mxf9cF7DzrT73i52k5zPHQA(thrd=0x0000000100019b40) + 21 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system/threads.nim:167:2
    frame #11: 0x0000000100009b00 start-addr:0x0000000100009afb  t12015 threadProcWrapper__KwtUyNVh00QDWGRZcngjGA(closure=0x0000000100019b40) + 48 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system/threads.nim:173:2
  frame #12: 0x00007fff6a72b109 libsystem_pthread.dylib`_pthread_start + 148
  frame #13: 0x00007fff6a726b8b libsystem_pthread.dylib`thread_start + 15
(lldb)
Process 36265 stopped
* thread #7, stop reason = EXC_BAD_ACCESS (code=1, address=0x1)
    frame #0: 0x0000000100003cf7 start-addr:0x0000000100003cf7  t12015 rawAlloc__mE4QEVyMvGRVliDWDngZCQ(a=0x0000000100017018, requestedSize=24) + 375 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system/alloc.nim:787:38
   784          result = c.freeList
   785          when not defined(gcDestructors):
   786            sysAssert(c.freeList.zeroField == 0, "rawAlloc 8")
-> 787          c.freeList = c.freeList.next
   788        dec(c.free, size)
   789        sysAssert((cast[ByteAddress](result) and (MemAlign-1)) == 0, "rawAlloc 9")
   790        sysAssert(allocInv(a), "rawAlloc: end c != nil")
Target 0: (t12015) stopped.
(lldb) bt
* thread #7, stop reason = EXC_BAD_ACCESS (code=1, address=0x1)
  * frame #0: 0x0000000100003cf7 start-addr:0x0000000100003cf7  t12015 rawAlloc__mE4QEVyMvGRVliDWDngZCQ(a=0x0000000100017018, requestedSize=24) + 375 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system/alloc.nim:787:38
    frame #1: 0x0000000100003fc5 start-addr:0x0000000100003fc0  t12015 alloc__UxtcZ3QOXKsB7mMchxUf9cg(allocator=0x0000000100017018, size=24) + 37 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system/alloc.nim:955:11
    frame #2: 0x0000000100004013 start-addr:0x0000000100004004  t12015 allocSharedImpl(size=24) + 51 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system/alloc.nim:1075:11
    frame #3: 0x000000010000405d start-addr:0x0000000100004058  t12015 allocShared0Impl__KzdpcuLT9aef9bsiSHlIu9aFg(size=24) + 29 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system/alloc.nim:1081:11
    frame #4: 0x0000000100005671 start-addr:0x000000010000566c  t12015 alignedAlloc0__tDURxGxuLs0hKEDbtrBxug(size=24, align=8) + 49 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system/memalloc.nim:351:12
    frame #5: 0x0000000100005453 start-addr:0x000000010000544e  t12015 newSeqPayload(cap=1, elemSize=16, elemAlign=8) + 291 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system/seqs_v2.nim:38:26
    frame #6: 0x0000000100005fee start-addr:0x0000000100005fe9  t12015 prepareSeqAdd(len=0, p=0x0000000000000000, addlen=1, elemSize=16, elemAlign=8) + 158 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system/seqs_v2.nim:57:12
    frame #7: 0x000000010000a1e1 start-addr:0x000000010000a1ce  t12015 setLen__GjRfWHdWvbN9c4UpEibA5yA(s=0x00007000013aef00, newlen=1) + 289 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system/seqs_v2.nim:125:30
    frame #8: 0x000000010000a239 start-addr:0x000000010000a234  t12015 eqcopy___r6aagoRVuov7HvfEjIi3Uw(dest=0x00007000013aef00, src=tySequence__sM4lkSb7zS6F7OVMvW9cffQ @ 0x00007000013aee70) + 41 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system.nim:2247:2
    frame #9: 0x000000010000d1cb start-addr:0x000000010000d1b4  t12015 sendHandler__zybol9an1ajv6WvIcP5tJgA_2 + 315 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system.nim:2247:2
    frame #10: 0x000000010000993c start-addr:0x0000000100009939  t12015 threadProcWrapDispatch__Mxf9cF7DzrT73i52k5zPHQA_2(thrd=0x0000000100019d70) + 28 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system/threads.nim:141:2
    frame #11: 0x0000000100009ac5 start-addr:0x0000000100009ac0  t12015 threadProcWrapStackFrame__Mxf9cF7DzrT73i52k5zPHQA(thrd=0x0000000100019d70) + 21 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system/threads.nim:167:2
    frame #12: 0x0000000100009b00 start-addr:0x0000000100009afb  t12015 threadProcWrapper__KwtUyNVh00QDWGRZcngjGA(closure=0x0000000100019d70) + 48 at  /Users/timothee/git_clone/nim/Nim_devel/lib/system/threads.nim:173:2
  frame #13: 0x00007fff6a72b109 libsystem_pthread.dylib`_pthread_start + 148
  frame #14: 0x00007fff6a726b8b libsystem_pthread.dylib`thread_start + 15

@timotheecour timotheecour changed the title example where std/channels is slower than system/channels_builtin or blocks std/channels is slower than system/channels_builtin or blocks (EDIT: gives EXC_BAD_ACCESS) Mar 18, 2021
@ringabout
Copy link
Member

ringabout commented Mar 23, 2021

@timotheecour

First example doesn't hang on my Linux machine

nim c --threads -d:newChan --gc:arc -d:danger -d:case10a2 -o:/tmp/z010a2 -g main.nim
for i in {1..200}; do /tmp/z010a2 ; done
0.1126968860626221
0.1075263023376465
0.1016650199890137
0.1080906391143799
0.1158299446105957
0.1163949966430664
0.1074697971343994
0.1044142246246338
0.1071176528930664
0.1214158535003662
0.1069133281707764
0.1073062419891357
0.1007535457611084
0.1037275791168213
0.1060914993286133
0.1148388385772705
0.1089463233947754
0.1062111854553223
...
etc

So does the second example

Maybe it is arch specific?

@timotheecour
Copy link
Member Author

timotheecour commented Apr 2, 2021

Maybe it is arch specific?

that's possible; I'm using osx 10.15.7, just retested "first example" now as of nim 2365b52 and it's the same as before, it hangs within < 10s.

@ringabout
Copy link
Member

ringabout commented Apr 2, 2021

Yeah, I tested it on ubuntu 20.04(it is the host system) (single core)
And VMware + manjaro(host system is windows) (four cores)
no hangs.

@timotheecour
Copy link
Member Author

timotheecour commented Apr 18, 2021

after #17717:

(note: i've in the meantime upgraded osx to big sur (11.2.3) from 10.15 but that shouldn't be related)

@xflywind can you reproduce the timing difference i'm noting for First example ?

@Araq
Copy link
Member

Araq commented Apr 19, 2021

Well ... can you find out why it is slower? :-)

@timotheecour
Copy link
Member Author

update: after trying #17884, nothing improved compared to what i wrote in #17392 (comment), and also there was 1 case where First example hanged; whether this relates to #17884 or not, I don't know; it's possible that in some cases, First example can still hang even without #17884

@narimiran
Copy link
Member

@xflywind can you reproduce the timing difference i'm noting for First example ?

For me, it is about 3x slower with newChan.

First example now does not hang anymore

Neither did for me the first time I ran it. But on repeated runs, sometimes it does run fine and sometimes it hangs at some random point (not the same one every time). See if you can reproduce it with multiple runs.

@timotheecour
Copy link
Member Author

But on repeated runs, sometimes it does run fine and sometimes it hangs at some random point

what frequency of the runs exhibits the hang, and for what nim commit? as of 8ce69d5 i can't reproduce the hang after running for i in {1..200}; do /tmp/z010a2 ; done 10 times (see #17392 (comment))

but i still observe the ~4x slowdown with -d:newChan (and the other points from #17392 (comment) still apply)

@narimiran
Copy link
Member

for what nim commit?

I was on ~30 commits old compiler. Now I updated to the latest commit (d67ae4afa) and re-run the example.

what frequency of the runs exhibits the hang

Out of 10 times I have run it, the hang happened 4 times. (And it is still ~3x slower)

@timotheecour
Copy link
Member Author

this is potentially related to #17946

@timotheecour timotheecour changed the title std/channels is slower than system/channels_builtin or blocks (EDIT: gives EXC_BAD_ACCESS) std/channels is slower than system/channels_builtin or hangs (EDIT: gives EXC_BAD_ACCESS) May 9, 2021
@ringabout
Copy link
Member

Ref #18801

@ringabout ringabout removed their assignment Sep 4, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

4 participants