Re: guile-2.9.2 and threading

[Mark H Weaver <mhw@netris.org>]

Hi Linas,

Linas Vepstas <linasvepstas@gmail.com> writes:

> I'm trying to understand how scm_jit_enter_mcode leads to
> scm_timed_lock_mutex ...

This simply means that 'lock-mutex' was called from Scheme, and
specifically from Scheme code that has been compiled to machine code by
our JIT compiler.

> I want to know who is attempting to lock, and why ... and how to work
> around this...

You'll need to look at the stack frames on the Scheme stack.  It can be
done from GDB if necessary, but it might be sufficient to use Guile's
debugger.

My first thought was to suggest ",break lock-mutex", but that doesn't
work, presumably because it's a C primitive (although we should fix
that), but I was able to patch in a pure Scheme wrapper for it, which
then allows us to set a Scheme breakpoint:

--8<---------------cut here---------------start------------->8---
mhw@jojen ~/guile-master$ meta/guile
GNU Guile 2.9.2.14-1fb399-dirty
Copyright (C) 1995-2019 Free Software Foundation, Inc.

Guile comes with ABSOLUTELY NO WARRANTY; for details type `,show w'.
This program is free software, and you are welcome to redistribute it
under certain conditions; type `,show c' for details.

Enter `,help' for help.
scheme@(guile-user)> ,use (ice-9 threads)
scheme@(guile-user)> (define (test n) (par-for-each + (iota n) (iota n)))
scheme@(guile-user)> (define core-lock-mutex lock-mutex)
scheme@(guile-user)> (set! lock-mutex (lambda* (mutex #:optional timeout)
                                        (core-lock-mutex mutex timeout)))
scheme@(guile-user)> ,break lock-mutex
Trap 0: Breakpoint at #<procedure lock-mutex (mutex #:optional timeout)>.
scheme@(guile-user)> (test 10000)
Trap 0: Breakpoint at #<procedure lock-mutex (mutex #:optional timeout)>
Entering a new prompt.  Type `,bt' for a backtrace or `,q' to continue.
scheme@(guile-user) [1]> ,bt
In current input:
      2:0  2 (test 10000)
In ice-9/threads.scm:
    389:6  1 (_ #<procedure 1307800 at ice-9/boot-9.scm:2698:7 ()>)
In current input:
     4:17  0 (lock-mutex #<mutex 1307f40>)
scheme@(guile-user) [1]> 
--8<---------------cut here---------------end--------------->8---

Hopefully this should be enough to figure out what's calling
'lock-mutex' in your case.

One possibility is that your code is accessing the module table too
often.  Does your code frequently call procedures like 'resolve-module',
'module-variable', 'module-ref', or any of the other procedures
documented in section 6.20.8 (Module System Reflection) of the Guile
manual?

> I'm using (ice-9 threads)   I see this:
>
> (define (n-par-for-each n proc . arglists)
>   (let ((m (make-mutex))
>    (threads '()))
>     (do ((i 0 (+ 1 i)))
>    ((= i n)
>     (for-each join-thread threads))
>       (set! threads
>        (cons (begin-thread
>          (let loop ()
>            (lock-mutex m)
>            (if (null? (car arglists))
>           (unlock-mutex m) 
>           (let ((args (map car arglists)))
>             (set! arglists (map cdr arglists))
>             (unlock-mutex m)
>             (apply proc args)
>             (loop)))))
>         threads)))))
>
> Oh, I says to myself: bad bad mutex. Let me write a lock-less loop: it
> chops the list into n pieces, each in its own thread. (a bit sloppy,
> but adequate):
>
> (define (my-for-each n proc args)
>    (define len (length args))
>    (define quo (euclidean-quotient len n))
>    (define rem (euclidean-remainder len n))
>    (define threads '())
>    (do ((i 0 (+ 1 i)))
>       ((= i n) (for-each join-thread threads))
>          (set! threads
>             (cons
>                (begin-thread
>                   (for-each proc (take (drop args (* i quo)) quo)))
>                threads)))
>    (for-each proc (drop args (* n quo)))
> )
>
> Let me go hog-wild: (my-for-each 12 proc list)   (I have a cpu with that many cores) So... what happens? A little better .. not much.  This time, gdb shows that there are four threads in my app.
> Two are stuck here:
>
> #0  __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
> #1  0x00007f343ca69bb5 in __GI___pthread_mutex_lock (
>     mutex=mutex@entry=0x7f343d4f0f40 <bytes_until_gc_lock>)
>     at ../nptl/pthread_mutex_lock.c:80
> #2  0x00007f343d213e20 in scm_gc_register_allocation (size=size@entry=16)
>     at ../../libguile/gc.c:591

This is the global GC allocation lock, which might be an issue if your
threads are performing a lot of heap allocation.

      Mark