Ann: SWI-Prolog 8.3.7

Dear SWI-Prolog user,

I’m happy to announce SWI-Prolog 8.3.7. This version comes with some
important fixes and improvements. Highlights:

  • Matt Lilley help finding a crash in the tabling test that notably
    occurred on (his) MacOS, but can in theory affect any version.

  • Fix to expand_file_name/2 for Windows on non-ascii file names.

  • Made frozen/2 compatible with SICStus, reporting all delayed
    goals (not only those from freeze/2) on all variables inside
    a given term (rather than only on the toplevel variable).

  • Handle arg/3 calls in the VM if the last argument is a first
    variable
    , i.e., known to be unbound by the compiler.

  • Avoid exception in markdown handling that can make parts of
    the documentation unavailable.

    Enjoy — Jan

SWI-Prolog Changelog since version 8.3.6

  • MODIFIED: Issue#665: Added read_term_with_history/2 and moved
    read_history to library(backcomp). read_term_with_history/2 provides
    access to all the read_term/2 options, notably the syntax changing
    options. After discussion with Robert van Engelen.

  • MODIFIED: qsave_program/2: preserve the autoload flag in the calling
    process and preserve autoloading if it is enabled and the save class is
    development

  • ENHANCED: frozen/2 to avoid copying. This not only enhances
    performance, but also maintains the variable identity.

  • FIXED: Possible crash in tabling, notably occurring on MacOS due
    to wrong assumptions wrt representing pointers in Prolog integers.
    With a lot of help from Matt Lilley.

  • FIXED: frozen/2 could fail after recent enhancements.

  • FIXED: Handle failure inside ‘fast’ opcodes which D_BREAK replaces
    with ‘slow’ opcodes that do not trigger FASTCOND_FAILED. To do this,
    if we hit D_BREAK and there is a fast condition pending, convert it
    into a real choicepoint

  • FIXED: Issue#657: Debug flags such as print_write_options in a
    saved state were overruled by the initialization. Robert van Engelen.

  • DOC: Issue#658: read_history/6 wrong info for substituting the
    event. Robert van Engelen.

  • ENHANCED: Compile simple arg/3 calls to the VM

  • ENHANCED: Allow listing and source level debugger to work for clauses
    the contain non-atom blobs.

  • MODIFIED: numbervars/4 using the singletons(true) option to
    number variables in LR order rather than in the order where the
    second occurrence is found. This notably makes the output of
    portray_clause/1-3 easier to read.

  • MODIFIED: frozen/2 now reports any goal that is delayed on some
    variable inside the first argument rather than only goals delayed
    due to freeze/2 and only checking for a direct variable.

  • MODIFIED: portray_clause/1,2,3: portray (a,b),c the same as
    a,(b,c). This is compatible with SICStus and makes sense as the
    compiler also compiles both shapes to the same code.

  • FIXED: Issue#652: expand_file_name/2 for Windows: double UTF-8
    encoding.

  • PPA: Removed eoan from PPA list

Package bench

  • PORT: Allow running on SICStus.

Package pldoc

  • FIXED: Markdown exception when processing a block like a code block
    followed by a possibly header underline (— or ===).

Package sgml

  • ADDED: XML space mode strict that never changes white space.
    Required for signature generation and checking. By Matt Lilley.

  • TEST: Syntax error. David Tonhofer.

2 Likes

Regarding the arg/3 optimization, is there any chance this could be extended for the case where the third argument is a nonvar, i.e., testing vs. generating?

With 8.3.7 it appears that arg(3,T,A), A=1 is faster than arg(3,T,1).

For some reason the build hangs afer the ssl test:

[...]
      Start  1: swipl:basic
      Start  2: swipl:unprotected
      Start  3: swipl:core
      Start  4: swipl:attvar
      Start  5: swipl:debug
      Start  6: swipl:tabling
      Start  7: swipl:library
      Start  8: swipl:compile
 1/70 Test  #8: swipl:compile ....................   Passed    0.21 sec
      Start  9: swipl:charset
 2/70 Test  #2: swipl:unprotected ................   Passed    0.41 sec
      Start 10: swipl:eclipse
 3/70 Test  #9: swipl:charset ....................   Passed    0.25 sec
      Start 11: swipl:clp
 4/70 Test  #4: swipl:attvar .....................   Passed    0.56 sec
      Start 12: swipl:GC
 5/70 Test #10: swipl:eclipse ....................   Passed    0.38 sec
      Start 13: swipl:save
 6/70 Test #11: swipl:clp ........................   Passed    0.45 sec
      Start 14: swipl:files
 7/70 Test #14: swipl:files ......................   Passed    0.21 sec
      Start 15: swipl:transaction
 8/70 Test #15: swipl:transaction ................   Passed    0.46 sec
      Start 16: swipl:xsb/basic_tests
 9/70 Test  #1: swipl:basic ......................   Passed    1.79 sec
      Start 17: swipl:xsb/ai_tests
10/70 Test  #5: swipl:debug ......................   Passed    1.79 sec
      Start 18: swipl:xsb/ptq
11/70 Test #16: swipl:xsb/basic_tests ............   Passed    0.93 sec
      Start 19: swipl:xsb/neg_tests
12/70 Test #18: swipl:xsb/ptq ....................   Passed    0.73 sec
      Start 20: swipl:xsb/delay_tests
13/70 Test #17: swipl:xsb/ai_tests ...............   Passed    0.83 sec
      Start 21: swipl:xsb/wfs_tests
14/70 Test  #7: swipl:library ....................   Passed    2.86 sec
      Start 22: swipl:xsb/table_tests
15/70 Test #13: swipl:save .......................   Passed    2.51 sec
      Start 23: swipl:xsb/incremental_tests
16/70 Test #19: swipl:xsb/neg_tests ..............   Passed    0.81 sec
      Start 24: swipl:xsb/nonmt_tests
17/70 Test #21: swipl:xsb/wfs_tests ..............   Passed    0.75 sec
      Start 25: swipl:xsb/sub_tests
18/70 Test #20: swipl:xsb/delay_tests ............   Passed    1.02 sec
      Start 26: swipl:thread
19/70 Test #23: swipl:xsb/incremental_tests ......   Passed    0.32 sec
      Start 27: swipl:thread_wait
20/70 Test #24: swipl:xsb/nonmt_tests ............   Passed    0.53 sec
      Start 28: chr:chr
21/70 Test #25: swipl:xsb/sub_tests ..............   Passed    0.65 sec
      Start 29: clib:cgi
22/70 Test  #6: swipl:tabling ....................   Passed    4.10 sec
      Start 30: clib:crypt
23/70 Test #29: clib:cgi .........................   Passed    0.11 sec
      Start 31: clib:memfile
24/70 Test #12: swipl:GC .........................   Passed    3.72 sec
      Start 32: clib:process
25/70 Test #30: clib:crypt .......................   Passed    0.24 sec
      Start 33: clib:readutil
26/70 Test #22: swipl:xsb/table_tests ............   Passed    1.49 sec
      Start 34: clib:socket
27/70 Test #31: clib:memfile .....................   Passed    0.25 sec
      Start 35: clib:af_unix
28/70 Test #33: clib:readutil ....................   Passed    0.13 sec
      Start 36: clib:stream
29/70 Test #35: clib:af_unix .....................   Passed    0.20 sec
      Start 37: clib:time
30/70 Test #36: clib:stream ......................   Passed    0.22 sec
      Start 38: clib:uri
31/70 Test #38: clib:uri .........................   Passed    0.25 sec
      Start 39: http:cgi_stream
32/70 Test #32: clib:process .....................   Passed    0.78 sec
      Start 40: http:http
33/70 Test #39: http:cgi_stream ..................   Passed    0.26 sec
      Start 41: http:json
34/70 Test #28: chr:chr ..........................   Passed    1.48 sec
      Start 42: http:multipart
35/70 Test #37: clib:time ........................   Passed    0.95 sec
      Start 43: http:proxy
36/70 Test #41: http:json ........................   Passed    0.49 sec
      Start 44: http:websocket
37/70 Test #40: http:http ........................   Passed    0.68 sec
      Start 45: nlp:nlp
38/70 Test #42: http:multipart ...................   Passed    0.48 sec
      Start 46: pengines:pengines
39/70 Test #27: swipl:thread_wait ................   Passed    2.23 sec
      Start 47: pengines:term_html
40/70 Test #45: nlp:nlp ..........................   Passed    0.14 sec
      Start 48: protobufs:protobufs
41/70 Test #48: protobufs:protobufs ..............   Passed    0.21 sec
      Start 49: RDF:rdf
42/70 Test #44: http:websocket ...................   Passed    0.48 sec
      Start 50: RDF:write
43/70 Test #47: pengines:term_html ...............   Passed    0.38 sec
      Start 51: semweb:con
44/70 Test #43: http:proxy .......................   Passed    0.69 sec
      Start 52: semweb:litmap
45/70 Test #49: RDF:rdf ..........................   Passed    0.19 sec
      Start 53: semweb:load
46/70 Test #51: semweb:con .......................   Passed    0.30 sec
      Start 54: semweb:ntriples
47/70 Test #50: RDF:write ........................   Passed    0.45 sec
      Start 55: semweb:rdf11
48/70 Test #52: semweb:litmap ....................   Passed    0.47 sec
      Start 56: semweb:rdf_db
49/70 Test #53: semweb:load ......................   Passed    0.44 sec
      Start 57: semweb:subprop
50/70 Test #54: semweb:ntriples ..................   Passed    0.21 sec
      Start 58: semweb:turtle2
51/70 Test #55: semweb:rdf11 .....................   Passed    0.33 sec
      Start 59: semweb:turtle
52/70 Test #58: semweb:turtle2 ...................   Passed    0.27 sec
      Start 60: sgml:sgml
53/70 Test #60: sgml:sgml ........................   Passed    0.16 sec
      Start 61: sgml:sgml_write
54/70 Test #56: semweb:rdf_db ....................   Passed    0.57 sec
      Start 62: sgml:xsd
55/70 Test #61: sgml:sgml_write ..................   Passed    0.22 sec
      Start 63: sgml:c14n
56/70 Test  #3: swipl:core .......................   Passed    7.45 sec
      Start 64: zlib:zlib
57/70 Test #62: sgml:xsd .........................   Passed    0.24 sec
      Start 65: bdb:bdb
58/70 Test #63: sgml:c14n ........................   Passed    0.19 sec
      Start 66: pcre:pcre
59/70 Test #66: pcre:pcre ........................   Passed    0.22 sec
      Start 67: yaml:yaml
60/70 Test #65: bdb:bdb ..........................   Passed    0.36 sec
      Start 68: jpl:prolog_in_java
61/70 Test #67: yaml:yaml ........................   Passed    0.21 sec
      Start 69: jpl:java_in_prolog
62/70 Test #64: zlib:zlib ........................   Passed    0.77 sec
      Start 70: ssl:ssl
63/70 Test #59: semweb:turtle ....................   Passed    1.81 sec
64/70 Test #34: clib:socket ......................   Passed    4.47 sec
65/70 Test #57: semweb:subprop ...................   Passed    2.66 sec
66/70 Test #46: pengines:pengines ................   Passed    3.96 sec
67/70 Test #69: jpl:java_in_prolog ...............   Passed    1.90 sec
68/70 Test #68: jpl:prolog_in_java ...............   Passed    2.14 sec
69/70 Test #70: ssl:ssl ..........................   Passed    4.23 sec
% It hangs here forever

SSL seems fine:

I do not see a return for zlib. Bit strange for that to hang. What does ps say? Can you attach a debugger to the hung process?

Here is the output from ps:

143699 pts/6    Sl+   27:52 /tmp/swi-prolog-devel/src/build/src/swipl -f none --no-packs -q /tmp/swi-prolog-devel/src/swipl-8.3.7/src/test.pl --no-core thread

Heres is the output from gdb:

Type "apropos word" to search for commands related to "word"...
Reading symbols from /tmp/swi-prolog-devel/src/build/src/swipl...
(No debugging symbols found in /tmp/swi-prolog-devel/src/build/src/swipl)
Attaching to program: /tmp/swi-prolog-devel/src/build/src/swipl, process 143699
[New LWP 143701]
[New LWP 145376]
[New LWP 145377]
[New LWP 145378]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/usr/lib/libthread_db.so.1".
0x00007f18f2bda8f0 in __pthread_clockjoin_ex () from /usr/lib/libpthread.so.0
(gdb) bt
#0  0x00007f18f2bda8f0 in __pthread_clockjoin_ex () from /usr/lib/libpthread.so.0
#1  0x00007f18f32a7ee6 in pl_thread_join2_va () from /tmp/swi-prolog-devel/src/build/src/libswipl.so.8
#2  0x00007f18f32e9cae in PL_next_solution () from /tmp/swi-prolog-devel/src/build/src/libswipl.so.8
#3  0x00007f18f3327d8b in query_loop () from /tmp/swi-prolog-devel/src/build/src/libswipl.so.8
#4  0x00007f18f3327c2c in prologToplevel () from /tmp/swi-prolog-devel/src/build/src/libswipl.so.8
#5  0x000055fea96f6059 in main ()
(gdb) 

Looks like a thread deadlock problem.

By the way, zlib finished:

62/70 Test #64: zlib:zlib ........................   Passed    0.77 sec

But thread did not finish:

Start 26: swipl:thread

We get there together :slight_smile: At least that makes a lot more sense. The thread tests are full of things that may deadlock if something goes wrong. What platform, compiler, etc.? Does this repeat (notably ctest -R thread)?

Yes, it reproduces all the time. This is on archlinux, gcc 10.2, libpthread 2.32 (from glibc 2.32).

I have never seen this problem before (I experience hanged tests before, but it had to do with ssl, not with threads).

Hmm. Doesn’t reproduce using gcc 10.0, glibc 2.31 (Ubuntu 20.04).

Not sure how to continue. Using ctest -V you get the command being executed. You can run this using gdb and examine the hung process and call PL_backtrace(25,0) in the appropriate thread.

To test some more I did the following:

  • did a ninja clean; ninja – everything worked fine
  • remove the cache for the package manager which I was using to install the new swi-prolog – voila! Everything worked.

The problem showed up using the aur package manager, but it cleared up once I made sure the build was done from scratch.

Must have been something leftover in the package manager cache. If it happens again I’ll let you know.

I am getting the problem again, but only if I run the package manager by itsef (after removing the package manager cache). This is what I get from ctest by running in the build tree produced by the package manager (Please see the first EDIT, I got a segfault with a nice backtrace):

ctest -V -R thread 
UpdateCTestConfiguration  from :/home/u/.cache/yay/swi-prolog-devel/src/build/DartConfiguration.tcl
UpdateCTestConfiguration  from :/home/u/.cache/yay/swi-prolog-devel/src/build/DartConfiguration.tcl
Test project /home/u/.cache/yay/swi-prolog-devel/src/build
Constructing a list of tests
Done constructing a list of tests
Updating test list for fixtures
Added 0 tests to meet fixture requirements
Checking test dependency graph...
Checking test dependency graph end
test 26
    Start 26: swipl:thread

26: Test command: /home/u/.cache/yay/swi-prolog-devel/src/build/src/swipl "-f" "none" "--no-packs" "-q" "/home/u/.cache/yay/swi-prolog-devel/src/swipl-8.3.7/src/test.pl" "--no-core" "thread"
26: Test timeout computed to be: 10000000
26: Running scripts from thread ............
26: WARNING: plunit_queue_gc:create: Did not reclaim queues in 10 runs.
26: This can be bad luck and is thus not considered a test failure.
26: WARNING: plunit_queue_gc:create: Did not reclaim queues in 10 runs.
26: This can be bad luck and is thus not considered a test failure.
26: plunit_queue_gc:create: Required 4 retrys before all queues were GCed

Perhaps this gives some more clues.

EDIT: I ran the ctest again and I got this:

ctest -V -R thread                                                                                                                                           
UpdateCTestConfiguration  from :/home/u/.cache/yay/swi-prolog-devel/src/build/DartConfiguration.tcl
UpdateCTestConfiguration  from :/home/u/.cache/yay/swi-prolog-devel/src/build/DartConfiguration.tcl
Test project /home/u/.cache/yay/swi-prolog-devel/src/build
Constructing a list of tests
Done constructing a list of tests
Updating test list for fixtures
Added 0 tests to meet fixture requirements
Checking test dependency graph...
Checking test dependency graph end
test 26
    Start 26: swipl:thread

26: Test command: /home/u/.cache/yay/swi-prolog-devel/src/build/src/swipl "-f" "none" "--no-packs" "-q" "/home/u/.cache/yay/swi-prolog-devel/src/swipl-8.3.7/src/test.pl" "--no-core" "thread"
26: Test timeout computed to be: 10000000
26: Running scripts from thread .............
26: plunit_queue_gc:create_non_empty: Required 4 retrys before all queues were GCed
26: ..............
26: SWI-Prolog [thread 23 () at Wed Sep  9 17:53:06 2020]: received fatal signal 11 (segv)
26: C-stack trace labeled "crash":
26:   [0] save_backtrace() at :? [0x7ff84fced3b6]
26:   [1] print_c_backtrace() at :? [0x7ff84fced4d9]
26:   [2] sigCrashHandler() at :? [0x7ff84fced5f6]
26:   [3] dispatch_signal() at :? [0x7ff84fd3b7ec]
26:   [4] __restore_rt() at sigaction.c:? [0x7ff84faa86a0]
26:   [5] lookupBlob.cold() at pl-atom.c:? [0x7ff84fc5918b]
26:   [6] lookupAtom() at :? [0x7ff84fcf5b25]
26:   [7] PL_unify_text() at ??:? [0x7ff84fd25eda]
26:   [8] concat.constprop.0() at pl-prims.c:? [0x7ff84fd34ee2]
26:   [9] pl_atom_concat3_va() at pl-prims.c:? [0x7ff84fd34d83]
26:   [10] PL_next_solution() at ??:? [0x7ff84fcf7413]
26:   [11] callProlog() at :? [0x7ff84fd15ca1]
26:   [12] start_thread() at pl-thread.c:? [0x7ff84fcb26ea]
26:   [13] start_thread() at pthread_create.c:? [0x7ff84f5e73e9]
26:   [14] __GI___clone() at :? [0x7ff84fb6b293]
26: Prolog stack:
26:   [3] system:atom_concat/3 [PC=1 in supervisor]
26:   [2] forall/2 [PC=11 in clause 1]
26:   [0] system:$c_call_prolog/0 [PC=0 in top query clause]
26: Running on_halt hooks with status 139
26: Killing 259596 with default signal handlers
1/2 Test #26: swipl:thread .....................***Failed    3.40 sec
test 27
    Start 27: swipl:thread_wait

27: Test command: /home/u/.cache/yay/swi-prolog-devel/src/build/src/swipl "-f" "none" "--no-packs" "-q" "/home/u/.cache/yay/swi-prolog-devel/src/swipl-8.3.7/src/test.pl" "--no-core" "thread_wait"
27: Test timeout computed to be: 10000000
27: Running scripts from thread_wait ......... done
27: All tests passed
2/2 Test #27: swipl:thread_wait ................   Passed    2.13 sec

The following tests passed:
	swipl:thread_wait

50% tests passed, 1 tests failed out of 2

Total Test time (real) =   5.53 sec

The following tests FAILED:
	26 - swipl:thread (Failed)
Errors while running CTest

EDIT2: Some more info. The problems seem to appear with PGO compilation only, with a PGO compiled binary sometimes I get these lines:

$ ctest -V -R thread 
[...]
26: WARNING: plunit_queue_gc:create: Did not reclaim queues in 10 runs.
26: This can be bad luck and is thus not considered a test failure.
26: WARNING: plunit_queue_gc:create: Did not reclaim queues in 10 runs.
26: This can be bad luck and is thus not considered a test failure.

It is not reproducible all the time, but the problem seems to appear only with PGO compilation.

Hard to tell. A crash in atom_concat/3 suggests memory management issues. Are you using tcmalloc() or the system malloc()? You might want to run the test under valgrind. Yes/no PGO more looks like a timing issue or unexpected instruction rescheduling that should have been protected using a memory barrier. Notably if it is timing it may of course also depend on the hardware (notably the number of cores).

Compiled using gcc-10 with PGO on Ubuntu 20.04. Works fine.

I didn’t make any malloc configuration changes, and the binary is linked with libtcmalloc_minimal, so I presume it is using tcmalloc.

I ran the test under valgrind:

  1. With the binary that I compiled myself (PGO/ninja), valgrind shows no leaks (valgrind --leak-check=full ctest -V -R thread )
  2. With the binary compiled by the aur package manager, it hangs just like it happens when I run it without valgrind.

The only difference that I can tell from my own compilation and the aur package manager compilation is the ‘-fPIC’ flag, this is how the aur package manager compiles it:

  cd build
  cmake ../swipl-$pkgver \
    -DCMAKE_BUILD_TYPE=Release \
    -DCMAKE_INSTALL_PREFIX=/usr \
    -DCMAKE_C_FLAGS="$CFLAGS -fPIC -ffile-prefix-map=$PWD= -w" \
    -DLIBEDIT_LIBRARIES=/usr/lib/libedit.so.0 \
    -DLIBEDIT_INCLUDE_DIR=/usr/include \
    -G Ninja
  ../swipl-$pkgver/scripts/pgo-compile.sh
  ninja

It’s a mystery.

We are not interested in leaks :slight_smile: Valgrind by default does all the sanity checks on memory handling. I think you are running valgrind on ctest though. You need to run ctest -V -R thread to find the command it executes and then run valgrind on src/swipl with the right options.

valgrind src/swipl option ...

Yes :frowning: The only suggestion I can think of is to build it exactly the way the package manager does (or at least as close as you get) and divide and conquer to find the option that matters. -fPIC can hardly be the issue as the real Prolog system is in libswipl.so and that is compiled with -fPIC anyway. This only causes the main executable swipl to be compiled with -fPIC, but I can hardly imagine that matters.

Here is the valgrind report (took a long time to finish):

$ valgrind  -s /home/u/.cache/yay/swi-prolog-devel/src/build/src/swipl -f none --no-packs -q /home/u/.cache/yay/swi-prolog-devel/src/swipl-8.3.7/src/test.pl --no-core thread
==391775== Memcheck, a memory error detector
==391775== Copyright (C) 2002-2017, and GNU GPL'd, by Julian Seward et al.
==391775== Using Valgrind-3.16.1 and LibVEX; rerun with -h for copyright info
==391775== Command: /home/u/.cache/yay/swi-prolog-devel/src/build/src/swipl -f none --no-packs -q /home/u/.cache/yay/swi-prolog-devel/src/swipl-8.3.7/src/test.pl --no-core thread
==391775== 
Running scripts from thread ................................................................
Warning: [Thread 23] thread_send_message/2: thread `<thread>(19,0x16939810)' does not exist
Warning: [Thread 23] thread_send_message/2: thread `<thread>(24,0x149ce610)' does not exist
Warning: [Thread 23] thread_send_message/2: thread `<thread>(24,0x15b4f260)' does not exist
Warning: [Thread 23] thread_send_message/2: thread `<thread>(19,0x149de990)' does not exist
............................... done
All tests passed
==391775== 
==391775== HEAP SUMMARY:
==391775==     in use at exit: 222,406,333 bytes in 46,648 blocks
==391775==   total heap usage: 65,023,084 allocs, 64,976,436 frees, 4,856,095,363 bytes allocated
==391775== 
==391775== LEAK SUMMARY:
==391775==    definitely lost: 2,312 bytes in 137 blocks
==391775==    indirectly lost: 0 bytes in 0 blocks
==391775==      possibly lost: 201,026,965 bytes in 304 blocks
==391775==    still reachable: 21,377,056 bytes in 46,207 blocks
==391775==                       of which reachable via heuristic:
==391775==                         newarray           : 40,368 bytes in 1,141 blocks
==391775==         suppressed: 0 bytes in 0 blocks
==391775== Rerun with --leak-check=full to see details of leaked memory
==391775== 
==391775== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 0 from 0)