Timing function problem

Q&A's, tips, howto's
Post Reply
cameyo
Posts: 115
Joined: Sun Mar 27, 2011 3:07 pm
Location: Italy

Timing function problem

Post by cameyo »

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

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)
)
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
Posts: 596
Joined: Fri Apr 08, 2005 7:13 pm
Location: Front Royal, Virginia

Re: Timing function problem

Post by rickyboy »

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!
(λx. x x) (λx. x x)

rickyboy
Posts: 596
Joined: Fri Apr 08, 2005 7:13 pm
Location: Front Royal, Virginia

Re: Timing function problem

Post by rickyboy »

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.
(λx. x x) (λx. x x)

cameyo
Posts: 115
Joined: Sun Mar 27, 2011 3:07 pm
Location: Italy

Re: Timing function problem

Post by cameyo »

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
Posts: 216
Joined: Mon Jun 02, 2014 1:40 am
Location: Melbourne, Australia

Re: Timing function problem

Post by ralph.ronnquist »

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
Posts: 115
Joined: Sun Mar 27, 2011 3:07 pm
Location: Italy

Re: Timing function problem

Post by cameyo »

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
Posts: 115
Joined: Sun Mar 27, 2011 3:07 pm
Location: Italy

Re: Timing function problem

Post by cameyo »

@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
Posts: 596
Joined: Fri Apr 08, 2005 7:13 pm
Location: Front Royal, Virginia

Re: Timing function problem

Post by rickyboy »

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
(λx. x x) (λx. x x)

rickyboy
Posts: 596
Joined: Fri Apr 08, 2005 7:13 pm
Location: Front Royal, Virginia

Re: Timing function problem

Post by rickyboy »

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
(λx. x x) (λx. x x)

cameyo
Posts: 115
Joined: Sun Mar 27, 2011 3:07 pm
Location: Italy

Re: Timing function problem

Post by cameyo »

@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
Posts: 596
Joined: Fri Apr 08, 2005 7:13 pm
Location: Front Royal, Virginia

Re: Timing function problem

Post by rickyboy »

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.
(λx. x x) (λx. x x)

cameyo
Posts: 115
Joined: Sun Mar 27, 2011 3:07 pm
Location: Italy

Re: Timing function problem

Post by cameyo »

@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
Posts: 596
Joined: Fri Apr 08, 2005 7:13 pm
Location: Front Royal, Virginia

Re: Timing function problem

Post by rickyboy »

cameyo, thank you for raising this issue!
(λx. x x) (λx. x x)

Lutz
Posts: 5282
Joined: Thu Sep 26, 2002 4:45 pm
Location: Pasadena, California
Contact:

Re: Timing function problem

Post by Lutz »

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
Posts: 115
Joined: Sun Mar 27, 2011 3:07 pm
Location: Italy

Re: Timing function problem

Post by cameyo »

@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
Posts: 5282
Joined: Thu Sep 26, 2002 4:45 pm
Location: Pasadena, California
Contact:

Re: Timing function problem

Post by Lutz »

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
Posts: 115
Joined: Sun Mar 27, 2011 3:07 pm
Location: Italy

Re: Timing function problem

Post by cameyo »

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
Posts: 5282
Joined: Thu Sep 26, 2002 4:45 pm
Location: Pasadena, California
Contact:

Re: Timing function problem

Post by Lutz »

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
Posts: 596
Joined: Fri Apr 08, 2005 7:13 pm
Location: Front Royal, Virginia

Re: Timing function problem

Post by rickyboy »

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!
(λx. x x) (λx. x x)

cameyo
Posts: 115
Joined: Sun Mar 27, 2011 3:07 pm
Location: Italy

Re: Timing function problem

Post by cameyo »

Thanks, Lutz !
Grazie Lutz !

Post Reply