Timing function problem

cameyo · Post by **cameyo** » Wed Sep 18, 2019 12:26 pm

I have a problem with the following function who merge two ordered lists in a new list.

(define (merge lstA lstB op)
  (define (ciclo out lstA lstB)
    (cond ((null? lstA) (extend (reverse out) lstB))
          ((null? lstB) (extend (reverse out) lstA))
          ((op (first lstB) (first lstA))
            (ciclo (cons (first lstB) out) lstA (rest lstB)))
          (true
            (ciclo (cons (first lstA) out) (rest lstA) lstB))))
  (ciclo '() lstA lstB)
)

Ascending order:

Code: Select all

(setq A '(1 2 3 4 5 6 7 8))
(setq B '(2 3 4 5 11 12 13))
(merge A B <)
;-> (1 2 3 4 4 5 5 6 7 8 11 12 13 18 19)

Descending order:

Code: Select all

(setq C '(4 3 2))
(setq D '(8 5 3 1))
(merge C D >)
;-> (8 5 4 3 3 2 1)

Now timing the function:

Code: Select all

(time (merge (sequence 1 500) (sequence 1 200) <) 500)
;-> 1751.43

Timing again:

Code: Select all

(time (merge (sequence 1 500) (sequence 1 200) <) 500)
;-> 2234.945

and again:

Code: Select all

(time (merge (sequence 1 500) (sequence 1 200) <) 500)
;-> 2672.319:

and again:

Code: Select all

(time (merge (sequence 1 500) (sequence 1 200) <) 500)
;-> 3015.992

Why does the execution time increase each time?
More: raising an error on REPL reset the problem
For example, type the following on REPL:

Code: Select all

and again:
;-> and@4098B4
;-> ERR: symbol expected : " again:"

Now timing the function will restart the problem:

Code: Select all

(time (merge (sequence 1 500) (sequence 1 200) <) 500)
;-> 1750.432
(time (merge (sequence 1 500) (sequence 1 200) <) 500)
;-> 2218.979

Does anyone know the explanation of this problem?
Thanks.
System: Windows 10 Pro 64bit - newLISP 10.7.5 64bit-utf8

rickyboy · Post by **rickyboy** » Wed Sep 18, 2019 5:17 pm

Yeah, I don't know precisely what's causing that, but when you use a loop (instead of an iterative recursive call), this problem goes away.

Code: Select all

(define (merge-via-loop lstA lstB op)
  (let (out '())
    (until (or (null? lstA) (null? lstB))
      (push (if (op (first lstB) (first lstA))
                (pop lstB)
                (pop lstA))
            out -1))
    (extend out (if (null? lstA) lstB lstA))))

First of all, I wouldn't use recursive tail calls for iteration in newLISP, as it doesn't optimize these calls (i.e., convert them to loops in the eval mechanism). Just use the loop constructs (while, for, etc.) for iteration.

Second, your non-idiomatic code has nonetheless uncovered an interesting behavior in newLISP. I would think that the time timings should NOT be increasing, yet they are. Very interesting. Hopefully, somebody smarter than I on this will reply. Thanks!

rickyboy · Post by **rickyboy** » Wed Sep 18, 2019 5:29 pm

P.S. Calling your merge function with smaller inputs doesn't cause a ramp up of timings.

Code: Select all

(setq C '(4 3 2))
(setq D '(8 5 3 1))
(time (merge C D >) 500)

Here's the REPL output as I continually press Ctrl-x Ctrl-e (newlisp-eval) with my cursor on the time call (in Emacs).

Code: Select all

> 2.712
> 2.777
> 2.682
> 2.69
> 2.648
> 2.658
> 2.677
> 2.645
> 2.651
> 2.633

Larger inputs will obviously get you a deeper call stack as you "fake" iterate down the input lists. So, the answer is probably somewhere there.

cameyo · Post by **cameyo** » Thu Sep 19, 2019 7:37 am

Thanks Rickyboy.
I known, the Scheme style is not suitable for newLISP :-)
But I'd like to know what creates the problem.
Time function or my merge function?
Have a nice day

ralph.ronnquist · Post by **ralph.ronnquist** » Thu Sep 19, 2019 8:06 am

Most likely it's the define in define, which probably ends up growing the symbol table for each new define in some way. You could compare with making it a heap based temporary function instead:

Code: Select all

(define (merge lstA lstB op)
  (let ((ciclo (fn (out lstA lstB)
                 (cond ((null? lstA) (extend (reverse out) lstB))
                       ((null? lstB) (extend (reverse out) lstA))
                       ((op (first lstB) (first lstA))
                        (ciclo (cons (first lstB) out) lstA (rest lstB)))
                       (true
                        (ciclo (cons (first lstA) out) (rest lstA) lstB))))
               ))
    (ciclo '() lstA lstB)
    ))

That should give the same result, except that the inner function is merely a heap element, and it does not add to the symbol table.

Of course I'm not sure exactly why the symbol table would grow, since the define clause, except for the first one, supposedly would merely redefine the ciclo, but maybe the reclaim of the discarded definitions has some kind of fault.

btw. what's wrong with:

Code: Select all

(define (merge lstA lstB op) (sort (append lstA lstB) op))

cameyo · Post by **cameyo** » Thu Sep 19, 2019 10:08 am

Thanks for the info.

btw. what's wrong with:
(define (merge lstA lstB op) (sort (append lstA lstB) op))

Nothing :-) It's ok.
But I would like to know the cause of the problem.
Have a nice day.

cameyo · Post by **cameyo** » Thu Sep 19, 2019 6:00 pm

@ralph.ronnquist:
I have tried your function (in a fresh REPL), but the result are the same:

Code: Select all

> (time (merge (sequence 1 500) (sequence 1 200) <) 500)
1842.392
> (time (merge (sequence 1 500) (sequence 1 200) <) 500)
2290.107
> (time (merge (sequence 1 500) (sequence 1 200) <) 500)
2831.184
> (time (merge (sequence 1 500) (sequence 1 200) <) 500)
2993.474

The time grow...

rickyboy · Post by **rickyboy** » Thu Sep 19, 2019 7:06 pm

cameyo wrote:@ralph.ronnquist:
I have tried your function (in a fresh REPL), but the result are the same:
Code: Select all
> (time (merge (sequence 1 500) (sequence 1 200) <) 500)
1842.392
> (time (merge (sequence 1 500) (sequence 1 200) <) 500)
2290.107
> (time (merge (sequence 1 500) (sequence 1 200) <) 500)
2831.184
> (time (merge (sequence 1 500) (sequence 1 200) <) 500)
2993.474
The time grow...

Not for me:

Code: Select all

$ newlisp
newLISP v.10.6.2 64-bit on BSD IPv4/6 UTF-8 libffi, options: newlisp -h

> (define (merge lstA lstB op) (sort (append lstA lstB) op))
(lambda (lstA lstB op) (sort (append lstA lstB) op))
> (time (merge (sequence 1 500) (sequence 1 200) <) 500)
578.678
> (time (merge (sequence 1 500) (sequence 1 200) <) 500)
578.9450000000001
> (time (merge (sequence 1 500) (sequence 1 200) <) 500)
580.067
> (time (merge (sequence 1 500) (sequence 1 200) <) 500)
583.557
> (time (merge (sequence 1 500) (sequence 1 200) <) 500)
583.6799999999999
> (time (merge (sequence 1 500) (sequence 1 200) <) 500)
582.287
> (time (merge (sequence 1 500) (sequence 1 200) <) 500)
581.162
> (time (merge (sequence 1 500) (sequence 1 200) <) 500)
582.919

rickyboy · Post by **rickyboy** » Thu Sep 19, 2019 10:01 pm

I upgraded my newLISP. Still works fine.

Code: Select all

$ ./newlisp
newLISP v.10.7.5 64-bit on BSD IPv4/6 UTF-8 libffi, options: newlisp -h

> (define (merge lstA lstB op) (sort (append lstA lstB) op))
(lambda (lstA lstB op) (sort (append lstA lstB) op))
> (time (merge (sequence 1 500) (sequence 1 200) <) 500)
594.7329999999999
> (time (merge (sequence 1 500) (sequence 1 200) <) 500)
594.78
> (time (merge (sequence 1 500) (sequence 1 200) <) 500)
596.348
> (time (merge (sequence 1 500) (sequence 1 200) <) 500)
596.448
> (time (merge (sequence 1 500) (sequence 1 200) <) 500)
596.001
> (time (merge (sequence 1 500) (sequence 1 200) <) 500)
595.079
> (time (merge (sequence 1 500) (sequence 1 200) <) 500)
594.71

cameyo · Post by **cameyo** » Fri Sep 20, 2019 6:01 am

@rickyboy and @ralph.ronnquist
Sorry, I didn't explain myself well. The function i tried was "merge" with temporary heap function.
The function with sort works well.
By the way, the fastest function is "merge-via-loop".
Thanks.

rickyboy · Post by **rickyboy** » Fri Sep 20, 2019 12:44 pm

cameyo wrote:@rickyboy and @ralph.ronnquist
Sorry, I didn't explain myself well. The function i tried was "merge" with temporary heap function.

Yes, you are correct. I remember testing this myself before I first posted here (as I had the same idea as Ralph). I ruled that out as a possibility when I saw what you saw: the timings still grew. And that’s why in my first post, I was willing to guess that the blame is the very large call stack (because the input lists were large enough). That’s why in my second post, I reported that much smaller input lists don’t seem to exhibit the problem.

Then I saw Ralph’s “let helper function” function, and I glossed over it (thinking, “yeah, I tried that; not gonna work”) and I got stuck on his sort-based function (because my thought was “oh yeah, duh; good one”) and to me THAT was “Ralph’s function”. :) (In my view, the let-helper version wasn’t his serious submission; he was using it as a vehicle to get us to investigate that avenue ourselves, like a good teacher who will not do all the work for his students. ;)

However, as I said, I still don’t know what causes this issue. I’m hoping that Lutz (there it is: I used the L word :) or another kind soul will look into it, because it looks to me to be more of a bug than a feature.

cameyo · Post by **cameyo** » Fri Sep 20, 2019 1:15 pm

@rickyboy:
i'm trying to solve the problem of time growing. I know that the Scheme style is not good for newLISP.
And yes, i'm a student...forever :-)
Thanks for the help.

rickyboy · Post by **rickyboy** » Fri Sep 20, 2019 1:36 pm

cameyo, thank you for raising this issue!

Lutz · Post by **Lutz** » Fri Sep 20, 2019 2:05 pm

On my system: MacBook (Retina, 12-inch, Early 2016), macOS Mojave v10.14.6
it looks different:

Code: Select all

newLISP v.10.7.5 64-bit on OSX IPv4/6 UTF-8 libffi, options: newlisp -h

> (define (merge lstA lstB op) (sort (append lstA lstB) op))
(lambda (lstA lstB op) (sort (append lstA lstB) op))
> (time (merge (sequence 1 500) (sequence 1 200) <) 500)
2260.89
> (time (merge (sequence 1 500) (sequence 1 200) <) 500)
2276.979
> (time (merge (sequence 1 500) (sequence 1 200) <) 500)
2238.431
> (time (merge (sequence 1 500) (sequence 1 200) <) 500)
2217.015
> (time (merge (sequence 1 500) (sequence 1 200) <) 500)
2238.752
> (time (merge (sequence 1 500) (sequence 1 200) <) 500)
2239.723
> (time (merge (sequence 1 500) (sequence 1 200) <) 500)
2217.198
>

It is going up and down in an oscillating manner.

cameyo · Post by **cameyo** » Fri Sep 20, 2019 2:52 pm

@Lutz:
Seems to me that you test the wrong function:

Code: Select all

(define (merge lstA lstB op) (sort (append lstA lstB) op))

This works well.
The "time growing" problem arise with the following two functions :

Code: Select all

(define (merge lstA lstB op)
  (define (ciclo out lstA lstB)
    (cond ((null? lstA) (extend (reverse out) lstB))
          ((null? lstB) (extend (reverse out) lstA))
          ((op (first lstB) (first lstA))
            (ciclo (cons (first lstB) out) lstA (rest lstB)))
          (true
            (ciclo (cons (first lstA) out) (rest lstA) lstB))))
  (ciclo '() lstA lstB)
)

(define (merge lstA lstB op)
  (let ((ciclo (fn (out lstA lstB)
                 (cond ((null? lstA) (extend (reverse out) lstB))
                       ((null? lstB) (extend (reverse out) lstA))
                       ((op (first lstB) (first lstA))
                        (ciclo (cons (first lstB) out) lstA (rest lstB)))
                       (true
                        (ciclo (cons (first lstA) out) (rest lstA) lstB))))
               ))
    (ciclo '() lstA lstB)
    ))

Lutz · Post by **Lutz** » Fri Sep 20, 2019 3:09 pm

Yes, using your definition of 'merge', time is increasing on my system too.

Code: Select all

> ./merge-time 
2837.097
(598 576460752303423488 418 3 0 2048 0 10878 10705 1411)
3596.99
(598 576460752303423488 418 3 0 2048 0 10878 10705 1411)
4144.72
(598 576460752303423488 418 3 0 2048 0 10878 10705 1411)
4526.995
(598 576460752303423488 418 3 0 2048 0 10878 10705 1411)
5021.806
(598 576460752303423488 418 3 0 2048 0 10878 10705 1411)
5475.793
(598 576460752303423488 418 3 0 2048 0 10878 10705 1411)
5927.577
(598 576460752303423488 418 3 0 2048 0 10878 10705 1411)
6196.546
(598 576460752303423488 418 3 0 2048 0 10878 10705 1411)
6451.934
(598 576460752303423488 418 3 0 2048 0 10878 10705 1411)
6576.566
(598 576460752303423488 418 3 0 2048 0 10878 10705 1411)
8244.489
(598 576460752303423488 418 3 0 2048 0 10878 10705 1411)
10133.406
(598 576460752303423488 418 3 0 2048 0 10878 10705 1411)
7734.864
(598 576460752303423488 418 3 0 2048 0 10878 10705 1411)
7595.829
(598 576460752303423488 418 3 0 2048 0 10878 10705 1411)
9027.866
(598 576460752303423488 418 3 0 2048 0 10878 10705 1411)
7656.296
(598 576460752303423488 418 3 0 2048 0 10878 10705 1411)
7687.444
(598 576460752303423488 418 3 0 2048 0 10878 10705 1411)
7974.064
(598 576460752303423488 418 3 0 2048 0 10878 10705 1411)
8514.397000000001
(598 576460752303423488 418 3 0 2048 0 10878 10705 1411)
8105.182
(598 576460752303423488 418 3 0 2048 0 10878 10705 1411)
~>

Also printing (sys-info) and you can see, there is no increase in stack levels or lisp cells between the calls to merge. I guess the answer is in stack and memory management of the underlying OS.

Code: Select all

(dotimes (i 20) 
	(println (time (merge (sequence 1 500) (sequence 1 200) <) 500))
	(println (sys-info)))

cameyo · Post by **cameyo** » Fri Sep 20, 2019 4:29 pm

Thanks Lutz.
Anyway i have found a strange thing: raising an error on REPL reset the time.
For example, type the following on REPL:

Code: Select all

(set)
ERR: missing argument in function set

Now timing the function will restart the problem (but time is reset to first value 1750.432):

Code: Select all

(time (merge (sequence 1 500) (sequence 1 200) <) 500)
;-> 1750.432
(time (merge (sequence 1 500) (sequence 1 200) <) 500)
;-> 2218.979
...

Lutz · Post by **Lutz** » Fri Sep 20, 2019 4:58 pm

Over time envrironment and stack memory gets fragmented by certain functions. The error forces a total low level freeing and reallocation of this memory. There is nothing we can do about it without slowing down everywhere, but it is a rare enough problem. Until now, I have never seen this before.

rickyboy · Post by **rickyboy** » Fri Sep 20, 2019 5:30 pm

Lutz wrote:Over time envrironment and stack memory gets fragmented by certain functions. The error forces a total low level freeing and reallocation of this memory. There is nothing we can do about it without slowing down everywhere, but it is a rare enough problem. Until now, I have never seen this before.

Thanks, Lutz!

cameyo · Post by **cameyo** » Fri Sep 20, 2019 6:25 pm

Thanks, Lutz !
Grazie Lutz !

newlispfanclub.alh.net

Timing function problem

Timing function problem

Re: Timing function problem

Re: Timing function problem

Re: Timing function problem

Re: Timing function problem

Re: Timing function problem

Re: Timing function problem

Re: Timing function problem

Re: Timing function problem

Re: Timing function problem

Re: Timing function problem

Re: Timing function problem

Re: Timing function problem

Re: Timing function problem

Re: Timing function problem

Re: Timing function problem

Re: Timing function problem

Re: Timing function problem

Re: Timing function problem

Re: Timing function problem