ciel-lang/CIEL

pretty-print-hash-table is not thread safe

Opened this issue · 2 comments

I was printing hash tables to debug a very concurrent program, and it would crash with:

The value
  -1
is not of type
  UNSIGNED-BYTE
when binding SB-PRETTY::COLNUM
   [Condition of type TYPE-ERROR]

Restarts:
 0: [ABORT] abort thread (#<THREAD "Anonymous thread" RUNNING {1004CD4883}>)

Backtrace:
 0: (PPRINT-TAB :LINE -1 1 #<SB-PRETTY:PRETTY-STREAM {10051B11A3}>) [external]
 1: ("fmt$~vt) " #<SB-PRETTY:PRETTY-STREAM {10051B11A3}> -1)
 2: (FORMAT #<SB-PRETTY:PRETTY-STREAM {10051B11A3}> #<FUNCTION "fmt$~vt) " {52E6EBDB}> -1)
 3: (FORMAT #<SB-PRETTY:PRETTY-STREAM {10051B11A3}> #<FUNCTION "fmt$~vt) " {52E6EBDB}> -1) [more]
 4: ((FLET "WITH-PRETTY-STREAM0" :IN SB-PRETTY::CALL-LOGICAL-BLOCK-PRINTER) #<SB-PRETTY:PRETTY-STREAM {10051B11A3}>)
 5: (SB-PRETTY::CALL-LOGICAL-BLOCK-PRINTER #<FUNCTION (FLET "PPRINT-BLOCK" :IN PRETTY-PRINT-HASH-TABLE) {7F098F0BE7EB}> #<SYNONYM-STREAM :SYMBOL SLYNK::*CURRENT-STANDARD-OUTPUT* {1004047373}> NIL NIL "" N..
 6: (PRETTY-PRINT-HASH-TABLE #<HASH-TABLE :TEST EQUAL :COUNT 2 {10051B0793}> #<SYNONYM-STREAM :SYMBOL SLYNK::*CURRENT-STANDARD-OUTPUT* {1004047373}>)
...

it seems all threads share the same *current-pprint-indentation*, and incf and decf is not atomic, so sometimes when two threads both incf at same time it will only increment once, or when two threads decf at same time it will only decrement once, for minimal example run:

(bt:make-thread
 (lambda ()
   (loop repeat 5000 do
     (pretty-print-hash-table
      (dict "one" "b"
            "c" (dict 4 5))))))
(bt:make-thread
 (lambda ()
   (loop repeat 5000 do
     (pretty-print-hash-table
      (dict "two" "b"
            "c" (dict 4 5))))))

randomly *current-pprint-indentation* will get incremented or decremented too much, you will either get that error as it reaches -1, or after finishing both threads it's value will be 5 or something rather than 1 as it should be.

I added *current-pprint-indentation* to the let binding at the start of pretty-print-hash-table in ciel.lisp:

(let ((*print-pretty* t)
        (*current-pprint-indentation* 1)
        (i 0))
...

so then each thread modifies it's own thread-local *current-pprint-indentation*. I don't know whether this is really a real issue as I should put some locking around debugging prints in multithreaded program anyway so the output doesn't get intermixed, but at least this way when I'm too lazy to add locking it's just some interleaved output rather than crashing

Thanks for the nice report.

I originally ported this function from Rutils to Serapeum.

https://github.com/ruricolist/serapeum/blob/master/REFERENCE.md#pretty-print-hash-table-ht-optional-stream

https://github.com/ruricolist/serapeum/blob/master/hash-tables.lisp#L568

rutils: https://github.com/vseloved/rutils/blob/master/core/hash-table.lisp#L120

So, I suggest you open an issue on Serapeum first and we see what happens?

Your solution is simple and non-intrusive so it looks like an acceptable patch.

interesting, it seems the issue isn't present though in the serapeum and rutils version, they are using pprint-indent to manage the nested indentation which works multithreaded where it seems in ciel that got replaced with *current-pprint-indentation* with the comment:

We use custom indentation instead of the pretty printer, because it doesn't print correctly in the shell (indentations are way too large).

I'm just using ciel in emacs repl where they both look the same with exception that the ciel version prints fresh-line at the end, but it's true in the ciel standalone shell the serapeum version has way too large indentation, I'm not sure what is difference between shell and repl that would cause it.