Racket 7.3 Plot Performance Regression

[evdubs]

Hi All,

I have noticed sluggish performance with my plot overlays in Racket 7.3 that I had not noticed in versions 7.2 and prior. Here's the code I am using to test (taken from here):

(require plot)

(define ((make-current-value-renderer fn) snip event x y)
  (define overlays
    (and x y (eq? (send event get-event-type) 'motion)
         (list (vrule x #:style 'long-dash)
               (point-label (vector x (fn x)) #:anchor 'auto))))
  (send snip set-overlay-renderers overlays))

(define snip (plot-snip (function sin) #:x-min 0 #:x-max (* 2 pi) #:y-min -1.5 #:y-max 1.5))
(send snip set-mouse-event-callback (make-current-value-renderer sin))
snip

With 7.3, it feels like the frame rate hovers around 5-10 fps and the mouse pointer input is buffered so you can move around the plot and it will slowly try to catch up to where your pointer was. 7.2 and prior all felt snappy and seemed to be at least 20-30 fps.

Here are my installation details:

Ubuntu 19.04

Intel Core i5-7400

16GB RAM with only ~10GB in use (no swapping) and <1GB in use by DrRacket

Racket 7.3 installed from the PPA

I asked Alex H. if he had noticed this regression and he said he had not. He uses Windows. I have not tried to see if the PPA version is any different from the official installer to see if there's a difference. Maybe that's the next step?

Evan

[Sam Tobin-Hochstadt]

I just tried this on my build (from HEAD) and I also do not see any
slowdown. Trying with a regular installer would be helpful.

Sam

> --
> You received this message because you are subscribed to the Google Groups "Racket Users" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to racket-users...@googlegroups.com.
> To view this discussion on the web visit https://groups.google.com/d/msgid/racket-users/b68b9731-3163-4d0b-9edc-32c3774b6243%40googlegroups.com.
> For more options, visit https://groups.google.com/d/optout.

[evdubs]

Thanks for trying it out.

I just tried using the bash installer from https://download.racket-lang.org/ and I experience the same issue of lagginess in 7.3. I also tried using a snapshot release from https://plt.eecs.northwestern.edu/snapshots/ and I experienced the same issue.

I am not sure what I should try next other than maybe profiling, but I have not had much luck making effective use of the profiler in the past for interactive applications.

Evan

> To unsubscribe from this group and stop receiving emails from it, send an email to racket...@googlegroups.com.

[Alex Harsanyi]

On Tuesday, June 4, 2019 at 11:32:42 AM UTC+8, evdubs wrote:

Thanks for trying it out.

I just tried using the bash installer from https://download.racket-lang.org/ and I experience the same issue of lagginess in 7.3. I also tried using a snapshot release from https://plt.eecs.northwestern.edu/snapshots/ and I experienced the same issue.

I am not sure what I should try next other than maybe profiling, but I have not had much luck making effective use of the profiler in the past for interactive applications.

Here are a few things you can try:

First, check again whether there’s a performance drop in Racket 7.2 too -- you

don’t want to spend time tracking down a Racket problem only to find out that

the latest Ubuntu update disabled the hardware acceleration on the graphics

card.

If it is indeed a regression in Racket 7.3, you can try narrowing the problem

down to either rendering or mouse event delays:

* you can measure the time it takes to render the plot by measuring the time

  the paint method of the `editor-canvas%`. You will need to create a custom

  `editor-canvas%` and override `on-paint` and use

  `current-inexact-milliseconds` to measure the time.

* to check if mouse events are delivered too late to the callback. You can use

  the `get-time-stamp` method on the event and compare it against

  `current-inexact-milliseconds` to determine the delay.

You will need to compare both values against Racket 7.2 to see which one is

causing the slow down.

Alex.

[evdubs]

Thanks for responding, Alex.

Here's what I came up with that I think satisfies your recommendations. It shows the sin() plot, expects interaction for 10 seconds, then prints min/max/mean/std dev for both the mouse-event-callback for the snip and on-paint for the editor-canvas%.

Here's the output from running that with Racket 7.2 and Racket 7.3.0.4:

$ ./racket-7.2/bin/racket ~/Code/racket/chart-lag-test.rkt
Mouse
Min: 1.115966796875
Max: 1209.123046875
Mean: 40.23961775104986
StdDev: 81.88591520019294

Paint
Min: 3.35302734375
Max: 275.579833984375
Mean: 79.6534423828125
StdDev: 113.45367443728956

$ ./racket-7.3.0.4/bin/racket ~/Code/racket/chart-lag-test.rkt
Mouse
Min: 1.072021484375
Max: 1095.2412109375
Mean: 21.93592705160883
StdDev: 54.53777963909044

Paint
Min: 3.18798828125
Max: 284.447998046875
Mean: 80.8831787109375
StdDev: 117.90272049413493

These numbers seem to suggest that 7.3 is an improvement, at least from the mouse-event stats, even though that is counter to the experience from interacting with the plot. Have any other ideas?

Evan

[Alex Harsanyi]

I had a look at the code and it is not exactly what I had in mind for the measurements.  The problem with your measurements is that the canvas is re-drawn only when needed, so the time between two calls to on-paint is not relevant for performance measurements.

For the on-paint, the time of the draw itself needs to be measured:

(define/override (on-paint)
  (define begin-timestamp (current-inexact-milliseconds))
  (super on-paint)
  (define end-timestamp (current-inexact-milliseconds))
  (set! paint-event-stats
        (update-statistics paint-event-stats (- end-timestamp begin-timestamp))))

For the mouse event, the time between when the event is created and the time it is passed to the callback:

(define ((make-current-value-renderer fn) snip event x y)

  (define delta (- (current-inexact-milliseconds) (send event get-time-stamp)))
  (set! mouse-event-stats (update-statistics mouse-event-stats delta))

  (define overlays
    (and x y (eq? (send event get-event-type) 'motion)
         (list (vrule x #:style 'long-dash)
               (point-label (vector x (fn x)) #:anchor 'auto))))
  (send snip set-overlay-renderers overlays))

Alex.

[evdubs]

I ran the program with your modifications, but counter to the documentation, the values I get from get-time-stamp don't seem at all similar to current-milliseconds or current-inexact-milliseconds. I ended up defining delta as follows (with 1559695139340 being a guess):

(define delta (- (current-inexact-milliseconds) 1559695139340 (send event get-time-stamp)))

Here are the results:

$ ./racket-7.2/bin/racket ~/Code/racket/chart-lag-test.rkt
Mouse
Min: 2.425048828125
Max: 97.818115234375
Mean: 30.901338585251057
StdDev: 28.349128820378922

Paint
Min: 0.282958984375
Max: 10.380859375
Mean: 4.27886962890625
StdDev: 4.162199753791872

$ ./racket-7.3.0.4/bin/racket ~/Code/racket/chart-lag-test.rkt
Mouse
Min: 2.034912109375
Max: 295.45703125
Mean: 54.28094064372857
StdDev: 40.51587689852278

Paint
Min: 0.177978515625
Max: 6.715087890625
Mean: 3.2418212890625
StdDev: 2.868002614564615

So this perhaps shows that mouse events are being triggered almost twice as slowly in 7.3, but I think my hack makes these numbers unreliable. Also, the latency experienced interacting with the plot seems much worse than just twice as slow. Are you at least able to see a disconnect between current-inexact-milliseconds and get-time-stamp?

Evan

[Alex Harsanyi]

On Wednesday, June 5, 2019 at 8:51:48 PM UTC+8, evdubs wrote:

I ran the program with your modifications, but counter to the documentation, the values I get from get-time-stamp don't seem at all similar to current-milliseconds or current-inexact-milliseconds. I ended up defining delta as follows (with 1559695139340 being a guess):

(define delta (- (current-inexact-milliseconds) 1559695139340 (send event get-time-stamp)))

On my machine, `get-time-stamp` always returns 0 -- this indicates that the event% object itself is copied somewhere along the way but the timestamp is not copied, The 1559695139340 is just the unix timestamp from when you ran the code first time.  I don't think the mouse test is relevant as is...  unfortunately I don't have any more suggestions for now...

Alex.

[Alex Harsanyi]

It looks like the `get-time-stamp` returns a value that is not what the documentation specifies and it is also platform specific, I created an issue with the relevant details here: https://github.com/racket/gui/issues/132

For now, I cannot think of a way to determine how old a mouse event is when the callback is invoked.

 

Alex.

[evdubs]

I changed the Linux line of code to:

[time-stamp (current-milliseconds)]

Is there a reason why you did not want to do that?

Any way, when I do that, here are the results I get:

$ ~/racket-7.2/bin/racket chart-lag-test.rkt
Mouse
Min: 0.132080078125
Max: 23.10107421875
Mean: 3.257062241367008
StdDev: 4.589805152078677

Paint
Min: 0.178955078125
Max: 102.94091796875
Mean: 28.86041259765625
StdDev: 42.84071031974706

$ ~/racket-7.3.0.4/bin/racket chart-lag-test.rkt
Mouse
Min: 0.126953125
Max: 202.34912109375
Mean: 25.70277455891149
StdDev: 38.4063903237421

Paint
Min: 0.175048828125
Max: 21.754150390625
Mean: 7.548767089843749
StdDev: 8.728339324923978

If this modification is okay, I guess this is getting somewhere?

Evan

[Alex Harsanyi]

The paint times for 7.2 seem inconsistent with your previous tests...

In any case, it seems mouse event handling takes longer in 7.3 based your results.  What happens if you update the callback to discard any mouse events older than, say 50 milliseconds?

Alex.

[evdubs]

 The paint times for 7.2 seem inconsistent with your previous tests...

Correct. That run was a bit of an outlier. The 7.2 runs are mostly in line with 7.3 with respect to paint.

Here's what I get for mouse callback stats with this code when I use different thresholds for delta:

Version	Min	Max	Mean	StdDev
7.2; delta < 2	0	22	3.398	3.968
7.3; delta < 2	0	210	4.795	18.214
7.2; delta < 20	0	22	2.332	3.64
7.3; delta < 20	0	206	9.728	19.46
7.2; delta < 200	0	106	2.961	7.802
7.3; delta < 200	0	239	29.579	34.369

With a smaller delta, more overlays are able to be shown in 7.3, but it is still noticeably laggy compared to 7.2 (looks like about a third of the frequency of updates). I suppose I can try this approach with my plot code if I upgrade to 7.3, but it's kind of upsetting.

Evan

[evdubs]

If anyone is following along here, I recently installed the Racket 7.4 (non-Chez Scheme) version from the Ubuntu PPA and this performance has been acceptable. It is slightly noticeably slower but much better than what I had seen in 7.3. This works for me, but I am still clueless in understanding what may have caused the performance drop as well as how to better profile/uncover what is happening in Racket programs in general.