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 69ff6c235a359bfe124e9079759d2df1c68eb5f7

$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 b590e3363f211a1003f6cd245973fe4eba00e4cf 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, 8831afafbb2c1a999f5f057d4010813f6546133a 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 40b2dac51a5f17ad49c5a045dcd42521751940a6

• 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 1a7ee6bd1c6dcff2b33eff94e4353954ff7555ab 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 1a7ee6bd1c6dcff2b33eff94e4353954ff7555ab 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 1a7ee6bd1c6dcff2b33eff94e4353954ff7555ab 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 40b2dac51a5f17ad49c5a045dcd42521751940a6 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 https://github.com/kevinlawler/kona/commit/69ff6c235a359bfe124e9079759d2df1c68eb5f7 it was 97 At the second commit of Jan 15, 2014 https://github.com/kevinlawler/kona/commit/b590e3363f211a1003f6cd245973fe4eba00e4cf it jumped to 151 At the first commit of Jan 31, 2015, https://github.com/kevinlawler/kona/commit/883140b2dac51a5f17ad49c5a045dcd42521751940a6 it jumped to 2221. The trim function was activated. At the sixth commit of May 11, 2015, https://github.com/kevinlawler/kona/commit/d1b37f7227fbc18f4ad36aed0e9ae0d57e0ea260 it fell to 116. The trim function was deactivated. At the second commit of Jul 28, 2015, https://github.com/kevinlawler/kona/commit/7e4f5fb6fe41af49406cd02257e1d5fbe76c0e6 it rose to 177. A slimmed down trim function was reactivated. At the commit of Aug 16, 2017, https://github.com/kevinlawler/kona/commit/8edd5d0ce5aed0c4e1d964aa9e2beb07685221db it jumped to 1141. Additional line-by-line syntax checking, issue #468. At the first commit of Aug 19, 2017, https://github.com/kevinlawler/kona/commit/f5029e7f2bb20edef489b869cfaba0d04867cb5a it jumped to 4743. Still more syntax checking, issue #468. At the first commit of Feb 12, 2018, https://github.com/kevinlawler/kona/commit/cd1365744b1abf0cd8247f394b26d0ad34fcae39 it jumped to 4847. Fix issue #490: Stack overflow. At the second commit of Feb 12, 2018, https://github.com/kevinlawler/kona/commit/d1cba0c3ddf007b0028c1c777412b70c030c7d40 it jumped to 6728. Fix issue #491: Pointer dereference. At the second commit of Mar 8, 2018, https://github.com/kevinlawler/kona/commit/47e77e92185bf5b933e7dcfef500ca12365efe18 it jumped to 9826. Fix issue #499: "Interesting case" ... more syntax checks. At the commit of Mar 20, 2022 https://github.com/kevinlawler/kona/commit/6b8927249e9dcb1e2231b6051a4bc0b2ca41005c 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.