Timer

[tavmem]

This bug became apparent when working on issue 615.

The command \l scrabble-puz.k seemed to run much faster in 32-bit k2.8 than in 64-bit kona.
When trying to examine just how much faster:

$rlwrap -n ./k
K 2.8 2000-10-10 Copyright (C) 1993-2000 Kx Systems
\ for help. \\ to exit.

  \t \l scrabble-puz.k
2

$rlwrap -n ./k
kona      \ for help. \\ to exit.

  \t \l scrabble-puz.k
value error
l
^
0

[tavmem]

This did work well and relatively fast (but ~50 times slower than k2.8) through the first commit done on Jan 15, 2014 69ff6c2

$git checkout 69ff6c235a359bfe124e9079759d2df1c68eb5f7
HEAD is now at 69ff6c2 fix case: d:.k;d:.k;d
$touch *.c
$make
...
$rlwrap -n ./k
K Console - Enter \ for help
  \t \l /home/tom/kona/scrabble-puz.k
97

Starting with the second commit of Jan 15, 2014 b590e33 it slowed down some and produced considerable extraneous output

$git checkout b590e3363f211a1003f6cd245973fe4eba00e4cf
HEAD is now at b590e33 fix #229: Scripts produce no output
$touch *.c
$make
...
$rlwrap -n ./k
K Console - Enter \ for help
  \t \l /home/tom/kona/scrabble-puz.k
>>  >  >>  >  >>  >  >>  >  >>  >  >>  >  >>  >  >>  >  >>  >  >>  >  >>  >  >>  >  >>  >  >> 
...
 ("abeklop"
  140 97 131 90 153 111 117)
...)
    151

Starting with the second commit of Nov 20, 2014, 8831afa we get:

• an extraneous error message
• less extraneous output
• similar speed

$git checkout 8831afafbb2c1a999f5f057d4010813f6546133a
HEAD is now at 8831afa activate 'open-in-next-line error'
$touch src/*.c
$make
...
$rlwrap -n ./k
K Console - Enter \ for help

  \t \l /home/tom/kona/scrabble-puz.k
...
 ("abeklop"
  140 97 131 90 153 111 117)
...)
open-in-next-line error

  112

Staring with the first commit of Jan 31, 2015 40b2dac

• it slows down considerably (now 1000 times slower than k2.8)
• the extraneous output remains

$git checkout 40b2dac51a5f17ad49c5a045dcd42521751940a6
HEAD is now at 40b2dac 'trim' avoids segfaults in corner cases within 'recur'
$touch src/*.c
$make
...
$rlwrap -n ./k
K Console - Enter \ for help

  \t \l /home/tom/kona/scrabble-puz.k
(("abcdeht"
  176 79 106 111 184 125 143)
...
 ("abeklop"
  140 97 131 90 153 111 117)
...)
open-in-next-line error
  2220

Starting with the commit of Mar 20, 2015 1a7ee6b we don't get a timer reading at all

$git checkout 1a7ee6bd1c6dcff2b33eff94e4353954ff7555ab
HEAD is now at 1a7ee6b better control re when 'Z K backslash_d(S s,I n,K*dict)' is executed
$touch src/*.c
$make
,,,
$rlwrap -n ./k
K Console - Enter \ for help

  \t \l /home/tom/kona/scrabble-puz.k
0
parse error
>  

[tavmem]

I backed out the changes made in the commit 1a7ee6b of Mar 20, 2015.
That commit was primarily aimed at issue #413.

Almost all of the problems mentioned in 413 remained fixed after the backout.
I will detail the exceptions later tonight.

[tavmem]

Issue 413 listed 4 cases causing segfaults in Kona.
After backing out the changes made 1a7ee6b to address 413, none of the 4 cases cause a segfault anymore

$rlwrap -n ./k
kona      \ for help. \\ to exit.

  (\\)
sh: -c: line 1: syntax error near unexpected token `)'
sh: -c: line 1: `\\)'
parse error
>  \
  
  if[1;\\]
  
  do[5;\\]
  
  ;\\
\\

in k2.8

$ rlwrap -n ./k
K 2.8 2000-10-10 Copyright (C) 1993-2000 Kx Systems
\ for help. \\ to exit.

  (\\)
\\
  
  if[1;\\]
  
  do[5;\\]
  
  ;\\
\\

So, instead of segfaults, we have an inconsistency in 1 case.
I will document this inconsistency as a separate issue.

Note, however, that in kona

$rlwrap -n ./k
kona      \ for help. \\ to exit.

  \t \l scrabble-puz.k
9684

This is nearly 5000 times slower than k2.8

[tavmem]

Removed the "trim" function that addressed recursion issues in 2015 in commit 40b2dac
Trim seems is no longer necessary ... all tests pass without it.
Now we have

$rlwrap -n ./k
kona      \ for help. \\ to exit.

  \t \l scrabble-puz.k
7725

kona is "only" about 3800 times slower thatn k2.8

[bakul]

May be time to do some profiling? Compile with the -pg option and then use gprof to look at where time is spent. Look at the man page for gprof on how to use it. This stackoverflow thread is worth reading: https://stackoverflow.com/questions/375913/how-can-i-profile-c-code-running-on-linux/

[tavmem]

Thanks! .
I will definitely check that out.

Meanwhile ... some more information on the progression of timings:
At the first commit of Jan 15, 2014 69ff6c2 it was 97
At the second commit of Jan 15, 2014 b590e33 it jumped to 151
At the first commit of Jan 31, 2015, 883140b it jumped to 2221. The trim function was activated.
At the sixth commit of May 11, 2015, d1b37f7 it fell to 116. The trim function was deactivated.
At the second commit of Jul 28, 2015, 7e4f5fb it rose to 177. A slimmed down trim function was reactivated.
At the commit of Aug 16, 2017, 8edd5d0 it jumped to 1141. Additional line-by-line syntax checking, issue #468.
At the first commit of Aug 19, 2017, f5029e7 it jumped to 4743. Still more syntax checking, issue #468.
At the first commit of Feb 12, 2018, cd13657 it jumped to 4847. Fix issue #490: Stack overflow.
At the second commit of Feb 12, 2018, d1cba0c it jumped to 6728. Fix issue #491: Pointer dereference.
At the second commit of Mar 8, 2018, 47e77e9 it jumped to 9826. Fix issue #499: "Interesting case" ... more syntax checks.
At the commit of Mar 20, 2022 6b89272 it fell to 7725. The trim function was deactivated again!

[tavmem]

Almost all of the delays are caused by 2 functions:

• trim: removes leading blanks and "extra" instances of each
• syntaxChk: does syntax checking

Deactivating trim brought the timing down to 7725.
Deactivating syntaxChk(in addition) brought the timing down to 167.

It seems that both of these functions are being interpreted/executed for each line as the file is read.
A better approach would be to load the complete file and then do the trim (if needed) and syntaxChk once, recursively.
There are 8473 items in the scrabble-puz.k file.

There may be addtional steps that are being done line by line.
Loading a scrabble-puz.k file with 30 items has a timing of 2.

[tavmem]

Having identified the problem here, I'm going to leave this as an open item.
In my opinion, crashes take a higher priority over something that works ... but is slow.
This was a detour in attempt to address issue #615.
Going back to 615.

[tavmem]

Note that issue #632 did identify a 3rd culprit for the slowness:
Too many calls of mmap

[tavmem]

Note that the original problem is with the command \t \l scrabble-puz.k
but when counting the executions of mmap issue #632 examined the command "file" 1: (4 5)
When we try the command \l scrabble-puz.k with strace using the file sp3.k with 3 records:

puz:(("abcdeht"
  176 79 106 111 184 125 143)
 ("abcdehu"
  105 73 77 102 109 57 63)
 ("abcdeik"
  118 80 87 129 147 106 87))

we find that kona executes mmap 6 times

\l sp3.k
) = 1 (in [0])
newfstatat(0, "", {st_mode=S_IFCHR|0620, st_rdev=makedev(0x88, 0), ...}, AT_EMPTY_PATH) = 0
read(0, "\\l sp3.k\n", 1024)            = 9
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=2004222}) = 0
openat(AT_FDCWD, "sp3.k", O_RDONLY)     = 3
close(3)                                = 0
openat(AT_FDCWD, "sp3.k", O_RDONLY)     = 3
close(3)                                = 0
openat(AT_FDCWD, "sp3.k", O_RDONLY)     = 3
newfstatat(3, "", {st_mode=S_IFREG|0644, st_size=126, ...}, AT_EMPTY_PATH) = 0
read(3, "puz:((\"abcdeht\"\n  176 79 106 111"..., 4096) = 126
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=2494395}) = 0
mmap(NULL, 2048, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fc43372b000
mmap(NULL, 128, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fc43372a000
mmap(NULL, 256, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fc433729000
mmap(NULL, 1024, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fc433728000
mmap(NULL, 512, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fc433727000
mmap(NULL, 64, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fc433726000
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=3042799}) = 0
read(3, "", 4096)                       = 0
close(3)                                = 0
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=3155739}) = 0
write(1, "  ", 2  )                       = 2
pselect6(1, [0], NULL, NULL, NULL, NULL

k2.8 does not execute mmap at all

\l sp3.k
) = 1 (in [0])
alarm(1)                                = 0
alarm(0)                                = 1
statx(0, "", AT_STATX_SYNC_AS_STAT|AT_NO_AUTOMOUNT|AT_EMPTY_PATH, STATX_BASIC_STATS, {stx_mask=STATX_BASIC_STATS|STATX_MNT_ID, stx_attributes=0, stx_mode=S_IFCHR|0620, stx_size=0, ...}) = 0
read(0, "\\l sp3.k\n", 1024)            = 9
alarm(1)                                = 0
stat64("sp3.k", {st_mode=S_IFREG|0644, st_size=126, ...}) = 0
stat64("sp3.k", {st_mode=S_IFREG|0644, st_size=126, ...}) = 0
stat64("sp3.k", {st_mode=S_IFREG|0644, st_size=126, ...}) = 0
openat(AT_FDCWD, "sp3.k", O_RDONLY)     = 3
statx(3, "", AT_STATX_SYNC_AS_STAT|AT_NO_AUTOMOUNT|AT_EMPTY_PATH, STATX_BASIC_STATS, {stx_mask=STATX_BASIC_STATS|STATX_MNT_ID, stx_attributes=0, stx_mode=S_IFREG|0644, stx_size=126, ...}) = 0
read(3, "puz:((\"abcdeht\"\n  176 79 106 111"..., 4096) = 126
read(3, "", 4096)                       = 0
close(3)                                = 0
brk(0x8919000)                          = 0x8919000
write(2, "  ", 2  )                       = 2
alarm(0)                                = 1
pselect6(1000, [0], [], NULL, NULL, NULL

[tavmem]

The primary reason that the command \t \l scrabble-puz.k takes so long appears to be improper placement of the call to the syntaxChk function.
If we add this single line to the beginning of the syntaxChk function so that we know how many times it is called and what is the parameter being checked

 Z I syntaxChk(S s)   //TODO: refactor the syntax check as a single pass
-{ if(s[0]=='\t' || s[0]=='\014') R 5;
+{ O("bgn syntaxChk   s:%s\n",s);
+  if(s[0]=='\t' || s[0]=='\014') R 5;

then, if we execute it on the sp3.k file described in the prior comment, we get

  \l sp3.k
bgn syntaxChk   s:\l sp3.k
bgn syntaxChk   s:puz:(("abcdeht"
  176 79 106 111 184 125 143)
 ("abcdehu"
  105 73 77 102 109 57 63)
 ("abcdeik"
  118 80 87 129 147 106 87))
bgn syntaxChk   s:("abcdeht"
  176 79 106 111 184 125 143)
 ("abcdehu"
  105 73 77 102 109 57 63)
 ("abcdeik"
  118 80 87 129 147 106 87))
bgn syntaxChk   s:"abcdeht"
  176 79 106 111 184 125 143)
("abcdehu"
  105 73 77 102 109 57 63)
("abcdeik"
  118 80 87 129 147 106 87)
bgn syntaxChk   s:"abcdehu"
  105 73 77 102 109 57 63)
("abcdeik"
  118 80 87 129 147 106 87)
bgn syntaxChk   s:"abcdeik"
  118 80 87 129 147 106 87)

syntaxChk is called 6 times (probably once for each time some portion of the file is "captured".
Note that the first time it checks the whole file, and then smaller portions on subsequent calls.

The full scrabble-puz.k file has 8,473 records spanning 16,946 lines.
syntaxChk would be called 8,476 times, once on the complete file, then on subsequently smaller portions!

[tavmem]

I made a better placement for syntaxChk
The result with kona

$ rlwrap -n ./k
kona      \ for help. \\ to exit.
  \t \l scrabble-puz.k
175

The result with k2.8

$ rlwrap -n ./k
K 2.8 2000-10-10 Copyright (C) 1993-2000 Kx Systems 
\ for help. \\ to exit.
  \t \l scrabble-puz.k
26

The remaining "slowness" of kona is probably due to the fact the kona uses mmap so much more then k2.8

In any event, this is no longer a bug, and the primary problem is fixed.
I will close this "bug" issue and reopen the "enhancement" issue #632 as a reminder to follow up on the mmap overuse in kona.