Mantis Bugtracker
  

Viewing Issue Simple Details Jump to Notes ] View Advanced ] Issue History ] Print ]
ID Category Severity Reproducibility Date Submitted Last Update
0002084 [Squeak] Morphic minor always 10-15-05 09:28 05-17-08 04:07
Reporter wiz View Status public  
Assigned To
Priority normal Resolution open  
Status new   Product Version 3.9
Summary 0002084: Each overlaping browser slows down screen updates considerably. Caching the image would speed things up.
Description For this one get a reasonably large animatedImageMorph (read in the animated gif SOURIN STARS.gif uploaded here for example)
add the frame rate watcher from widgets to the world in an out of the way place.

On my iMac 400hz the animation full throtle frame rate is 100ms = 10/sec.

open some browsers (I used the debug handle to open one on the morph class and just copied that several times.)

Put the animated morph in front of the browsers.

With each browser on my machine the frame rate slows by another 100 ms approximately. If the animated morph doesn't overlap the frame rate is not very much affected by the browsers.

Now instead get a full size image of the browser. ( export import or from a workspace "browertextreference imageForm asMorph openInHand)

Collapse the browsers to get them out of the way and put their images in the same configuation.
The frame rate remains around 100ms.

Additional Information The logical conclusion from this is that if system windows would cache their images that would REALLY speed things up.

If you are worried about liveliness and updatedness then if all system windows would take turns updating thier caches that would insure they were up to date and maintain a reasonable frame rate. And of course a specific change notification could trigger the cache update.

Taming system window updating is clearly a key to getting squeak to perform. Most systems these days will have the memory for the caching (at 100ms/sys window/frame how much memory would you trade to get that time back?)

The other thing that would clearly help is minimizing the sys window size defaults. The smaller they are the less chance for overlap and interference and the further any memory caching scheme would go for a given amount of memory.
Attached Files  SOURIN STARS.gif [^] (14,946 bytes) 10-15-05 09:28
 6680browben.text [^] (546 bytes) 05-01-08 23:48
 changesforsq6685..6686 [^] (94,605 bytes) 05-01-08 23:56
 BrowserBenchmark.st [^] (2,830 bytes) 05-02-08 11:05

- Relationships

SYSTEM WARNING: Creating default object from empty value

child of 0006567new  Mother of Morphic Cleanup Tweak 
child of 0006876new  Why is my UI slow? 

- Notes
(0002903 - 1422 - 1560 - 1560 - 1560 - 1560 - 1560)
Eddie Cottongim
10-19-05 18:09

My thoughts:
Caching as you point out is expensive in terms of memory. 2 Megs for say a 800x600x32 SystemWindow. The systems that suffer for speed also typically don't have a ton of memory. But its also not free in terms of time; you have to keep them updated, and Bitblt while fast isn't anywhere close to free. So I'd be hesitant to cache everything.

But obviously morphic is being fairly stupid here: The damaged region is completely covered by one Morph. There are others behind it, but they don't need to be redrawn.

So, I would consider some more smarts in the damage/update logic here before I'd try caching everything.

The current logic is something like (off top of my head):

Collect/merge damaged regions
Redraw any morph touching the damaged region back to front.

What would seem to solve your problem is:

Collect/merge damage
Collect morphs touching damage
Discard morphs whose damaged portion is completely obscured
draw visible morphs back to front

In your example, we'd only be drawing the animation each time. This sorting occlusion testing has some cost but its way faster than redrawing everything and probably faster than caching would be too, without the memory cost.

This is just first pass brainstorming but it might be one of those areas that Tim R has pointed out as scaling really poorly.

Assumingly I'm remembering this junk right; I'll look more when I get home.
 
(0002948 - 637 - 671 - 671 - 671 - 671 - 671)
Eddie Cottongim
10-21-05 15:25

Ok, forget that stuff I said. Morphic already does it.

The problem is that AnimatedImageMorph thinks it could be transparent, and forces the stuff behind it to be redrawn. If you override areasRemainingToFill to be something like "^aRectangle areasOutside: bounds" it will run at full speed no matter what it is on top of (will still be slow if other stuff is on top, but thats more understandable). Really this should go in Image since it applies there too. Unfortunately I don't know how to test cheaply for transparency anywhere in the image.

There are probably several other Morphs that don't behave optimally in this respect.
 
(0002954 - 818 - 878 - 878 - 878 - 878 - 878)
wiz
10-24-05 08:04

Hi Eddie,

Thanks for looking at this. I was hoping it would get your attention.

I've been curious as to what slows Morphic down and this was a good reproducable example.

I've seen and wondered about cost of not getting a good transparency test. Now we know it can be high.

The anigif was just a good way of getting the system windows to redraw themselves frequently to get a handle on how much time they spent doing the redrawing. The overlapping windows each add 100ms to the per frame draw time. Even if the gif wasn't causing constant redraws five overlaping windows will cost half a second each time something causes the top one to redraw. Thats the essence of the slowness.

The text in a system window has a transparent background. I wonder if thats causing part of the massive redraw problem?
 
(0003394 - 3821 - 4193 - 4193 - 4193 - 4193 - 4193)
wiz
12-28-05 07:50
edited on: 12-31-05 04:19

More data:

To get the matter of the hdwe out of the way I'm still on my iMac.
OS9.1 running a fresh squeak3.9a 6706 image w/ Sq3.8.8b15 vm.

I read in the animated morph SOURIN STARS.gif uploaded here.
Please note the animorph is being used as a probe, a constant irritant if you will, to allow me to look at the frame rate while things are changing the image once a frame. What I am trying to track down is what makes system windows and particularly system windows with pluggable lists in them slow when changes are happening. And what makes the slowness cascade as more windows are overlapping each other.

Got a framebuffer morph and put it out of the way in the upper right corner.

With just that things run at about 16-18 ms to the frame sometimes slower.

Putting an opaque rectangle over the animated morph and it now the frame rate takes just 4 ms.

Deleting the rectangle then collapsing the animated morph the frame rate becomes 2 ms.

Open a class browser. fr still 2 ms.
Select Kernel-Numbers. Select LargePositiveIntegers. There are now four browser lists displayed. the fr remains 2 ms.

Uncollapse the animated morph but arrange it so it is not overlapping anything. the fr drops to 16-24 ms sometimes as low as 36 ms frame.

Collapse the browser. Make sure it doesn't overlap. fr remains 16-24 ms sometimes as low as 36 ms frame.

Now overlap a portion of the collapsed browser over the animorph. fr drops to 118-124 ms. Do you find this odd?

If the collapsed browser is put totally within the bounds of the animorph the fr slows to 125-130 ms.

Putting the animorph on top ( which in the later case totally obscures the collapsed browser) does not change the frame rate.

If I collapse the browser and obscure the animorph with an opaque rectangle again the fr speeds up to 4ms.

Now if I uncolapse the browser. So that it obsures the rectangle that obscures the animorph the frame rate becomes 206-212 ms. This is odd and unexpected. What is happening here?

the answer is the key to returning squeak to a higher level of preformance.

Just to check I collapsed al 3 morphs. fr 2 ms.
Uncollapsed just the rectange and then the browser. fr 2 sec.

Uncollapse all three but had the rectange obscure the browser which was over the animorph. fr 4 ms.

Leaving the browser over the animorph I resized the rectange to just expose the second text field (the class comment for the selected class large integer morph. fr 10 ms.

Exposing both text fields (the class definition and comment.) made the fr slow to 100 ms. Odd, and I think key to the puzzle.

Duplicating the rectangle and using this as a mask for the lower text field. The fr goes back to 10ms.

Using the second rectange to hide just the line between the fields or to hide the scroll bars on the right but leave both texts exposed slows things back to the fr of 100ms.

So the text not the decorations are causing a nonlinear slow down. Hmmm.

There are more variation to try. I've been doing them on the fly as I write this report and I've gotten to the end of my concentration for now.

I know the text fields are being drawn with a transparent background. Somehow this seems to be causing what ever is beneath to be redrawn as well. Something non-linear is happening which is making matters worse. And a big performance hit happens for each change. When a text is being edited this has been notable and I've seen a goodly number of complaints.

Whats causing it?

I don't have a enough knowledge to even begin to know where to look.
A good experiment would be to change things about the way that text is drawn until something effects a positive change in the frame rate.
An opaque backgound for text would be a good place to start.

Any experimenters out there?

 
(0004903 - 1579 - 1649 - 1649 - 1649 - 1649 - 1649)
dway
05-13-06 01:31

These are some important performance problems... slow browser redrawing is something I definitely notice once I've opened several browsers, it's probably the most noticeable "slowness" in Squeak for me, and for a lot of people.

Have you tried MessageTally to get some clues as to what's going on? To try it, in this case you'd set up your morphs in one of your fast framerate configurations, go to World Menu->debug->start/browse MessageTally, then let it run for 10 secs or so before you move the cursor to the top of the screen to see your tally results. Then do the same thing with a slow framerate configuration, and compare the different tally results.

Trying it myself, I have to admit I don't see a big difference in the stacks for either configuration. You can see, though, that the SystemWindow>>fullDrawOn: is taking the bulk (80%+) of the time in either scenario, no surprise there. Also, I see in the stack that ProportionalSplitterMorph is taking a lot of time, which I thought was a red flag at first (this resizing morph is the problem!) but then I realized it probably just acts as a wrapper morph so naturally it's going to take a fair amount of time to draw the stuff inside it (the text inside the panes).

Anyway, the MessageTally is key here just to get a starting point to figure out what the code is doing. It's still not easy, but for me it would be impossible to even know where to start without it.

But yeah, I wouldn't be surprised if the transparent backgrounds behind the text in browsers may be causing a pretty big hit. (or not :) )
 
(0004922 - 1111 - 1207 - 1207 - 1207 - 1207 - 1207)
wiz
05-15-06 09:38

Hi Doug,

Thanks for your suggestions.

I'm not familiar enough with MessageTally to use it to hone in further on the observations I've already made.

The important question to me is to find out what is being invoked in one case that is not being invoked in the other. My suspicions are that there is some timing cascade that causes large things to be re-evaluated when they don't need to be. Possibly several times per frame. The wide difference between frame times is a clue. Lazy lists looked like a good candidate for a while.

I haven't had the time/interest to make this a priority. So I've settled for reporting my observations in hopes of tweaking the curiosity of someone who had the ability to swiftly narrow the area of search. Or even come up with the culprit/solution.

My motivation is similar to yours. The problems here indicate a large performance hit that SHOULD be correctable. There's a sweet feeling of frustration with this that suggests a solution hides nearby.

And the payoff is HUGE.

So maybe this report will find some hunters.

Yours in service, -- Jerome Peace
 
(0005017 - 1385 - 1553 - 1553 - 1553 - 1553 - 1553)
wiz
05-20-06 08:43

More analysis,

For this one in a fresh 7032.
Clear the screen by deleting workspaces.

Get a new workspace and in it evaluate.

TimeProfileBrowser onBlock:
[ 3 timesRepeat: [ Transcript open show: 100 factorial printString ]].

Close the TimeProfileBrowser .
Delete the three transcripts.
Increment the number of times to repeat.

Now compare the two tallies.

YMMV but my result showed that adding just one more iteration doubled the time it took every thing to happen.

(This is a slight modification of the example used on the swiki for the TimeProfileBrowser. When I originally tried it the iterations were still at 20. Boy was that slow.)

As I mentioned before I don't know a really good way to glean understanding from the Tally. It just lumps all the time together and is spending 9-10% in BalloonEngine>> doLoopFaster)

The interesting thing to observe is that show transcript updates the oldest (deepest z) transcripts first, then the ones on top of it. etc.
Now if each of those does a self change causing the ones below it to redraw. Then instead of four things updating you have 1+2+3+4 = 10. And of course the deeper the larger the trangle number acends.

This could be a likely candidate for what we are seeing with browsers.

I don't claim this to be true. Its just a suspicion worth reporting. You can try the example for yourself.
 
(0006164 - 1200 - 1477 - 1477 - 1477 - 1477 - 1477)
wiz
07-23-06 01:37

Ha. found another clue.

To observe.

In a fresh 7046 (or previous) squeak.

0) set preferences: show annotation panes.
and from the annotation browser.

select:
timeStamp
messageCategory
implementorsCount
sendersCount
priorVersionsCount
allChangeSets

and click apply




1) World Menu>open>packageBrowser
2) Select package subpackage and catagory but don't select a method.
     I used ( Kernel numbers LargeNegativeInteger testing)
3) Using the halos collapse the package.
4) Now uncollapse it. (Observe: It comes back quickly)

Compare with
5) select a method (I used #positive)
6) Collapse
7) Uncollapse (Observe the hour glass comes on and you can count off several seconds before the browser comes up.

8) go back to the preferences and disable annotation panes
9) get a new browser and try the same experiment.
10) the hour glass does not appear and thing are fairly fast again.

So the annotations are adding a lot to the slow down. Smarter updating for annotation panes would speed things a lot.

I haven't check into which annotation are slowing things down. It is probably the ones checking prior versions.

Yours in service, -- Jerome Peace
 
(0012046 - 1050 - 1145 - 1145 - 1145 - 1145 - 1145)
wiz
05-01-08 23:55
edited on: 05-02-08 00:38

a recent post suggested a bench mark and pointed out the problem of slow browsers started in 3.9

I did some additional benchmarks with differnent 3.9 alpha's and found the change occured between images 6684 and 6686. Looking at the changesets apparently a bunch of changes affected browsers in update 6685 then 6686 was just a postamble doit to set preferences.
The uploaded 6680browben.text contains the benchmark doit and various times (on a 400hz imac running os9.1)

The benchmarks are good enough to pinpoint the change.

Since the intermediate 3.9's are no longer on the ftp site I will upload the relevant portion of the change file from 6686.

I've used the changefile rather than the change set because the switch to MC for updates in 3.9 and the extensiveness of the changes for this meant it would have been much more work to fileout and upload the change sets themselves.

My observation is that 3.9 made squeak much harder to maintain (from a bug trackers point of view).
 
Yours in curiosity and service, --Jeorme Peace

 
(0012047 - 802 - 985 - 985 - 985 - 985 - 985)
mberth
05-02-08 11:12

The problem is definitely related to using rounded corners for windows. I have attached class BrowserBenchmark that nicely prints a benchmark in the transcript. In a 3.9.1 image I get the slowdown when I use rounded corners. Switching to rectangular corners in Preferences cures it. I am using default font choices for this (World menu -> appearance -> system fonts -> restore default font choices) i.e. no truetype in main areas of windows.

Measuring browser speed: base.4.image
Preferences roundedWindowCorners -> true
SystemWindow new hasDropShadow -> true

781
964
1085
1379
1383
1511
1643
Slowdown: 2.1


Measuring browser speed: base.4.image
Preferences roundedWindowCorners -> false
SystemWindow new hasDropShadow -> true

724
799
783
805
773
806
811
Slowdown: 1.12
 
(0012048 - 487 - 676 - 676 - 676 - 676 - 676)
mberth
05-02-08 11:18

Some TrueType fonts (World menu -> appearance -> system fonts -> demo mode), square corners

Measuring browser speed: base.4.image
Preferences roundedWindowCorners -> false
SystemWindow new hasDropShadow -> true

1375
1462
1427
1449
1462
1812
1924
Slowdown: 1.4


Same with round corners:
Measuring browser speed: base.4.image
Preferences roundedWindowCorners -> true
SystemWindow new hasDropShadow -> true

1192
1713
2114
2490
2887
3769
4166
Slowdown: 3.49
 
(0012050 - 827 - 1097 - 1097 - 1097 - 1097 - 1097)
mberth
05-03-08 05:56

Here are some more measurements (on a macbook pro), repeat these by filing in BrowserBenchmark.st and then open a Transript window, and execute BrowserBenchmark browserIsQuick in a workspace.

Measuring browser speed: Squeak3.8.1-6747.image
Preferences roundedWindowCorners -> true
SystemWindow new hasDropShadow -> false

252
245
245
251
236
245
257
Slowdown: 1.02

Interestingly, in 3.9a-6686 we see slowdown even with square corners:

Measuring browser speed: Squeak3.9a-6686.image
Preferences roundedWindowCorners -> false
SystemWindow new hasDropShadow -> true

250
376
489
608
725
847
975
Slowdown: 3.9


Measuring browser speed: Squeak3.9a-6686.image
Preferences roundedWindowCorners -> false
SystemWindow new hasDropShadow -> true

246
383
494
599
720
854
963
Slowdown: 3.91
 
(0012052 - 826 - 938 - 938 - 938 - 938 - 938)
wiz
05-03-08 23:07

Ha.

Running the benchmark with showdamage on (PreferenceBrowser>Debug>debugShowDamage) is enlightening.

In 6686 the screen damage from the browser includes the display top left and the browser bottom right. This should not be.

In 6684 the damage is confined to the browser and often just the list pane being updated.

Now I thought that Karl proposed a fix that got into 3.10 or maybe even 3.9 final so this may have changed.

The curiosity is what culprit(s) are causing the over-damage?

One good suspect is the pane splitters they are deleted then added around the screen updates in code introduced in 6685. So that is a significant change and wildly extravagent in terms of processing.

First good tests. Then I'll think more about solutions.

As my favorite dectective would say: "The games afoot."
 
(0012053 - 1178 - 1410 - 1674 - 1674 - 1674 - 1674)
mberth
05-04-08 00:02

I did not know that I could re-create the intermediate images, from the Squeak3.9a-6678.image that is available on ftp to the Squeak3.9a-6685.image, by running

  Utilities updateFromServerThroughUpdateNumber: 6685.

(that uses the update stream mechanism, http://wiki.squeak.org/squeak/486) [^] That confirmed that the problem (or a similatr one) was absent in 6684. 6685 is the first update that shows the slowdown, although there it occurs with both rounded and square corners. Here are my benchmark results for 6685:

Measuring browser speed: Squeak3.9a-6678-work-6685.image
Preferences roundedWindowCorners -> true
SystemWindow new hasDropShadow -> true

316
465
607
760
896
1034
1173
Slowdown: 3.71


Measuring browser speed: Squeak3.9a-6678-work-6685.image
Preferences roundedWindowCorners -> false
SystemWindow new hasDropShadow -> true

309
453
593
732
1000
1002
1131
Slowdown: 3.66

That suggests that another problem / slowdown was introduced that was later corrected, at least for square corners.

If you want to look at the changeset go to http://ftp.squeak.org/updates/6685Release4-md.cs [^] - it loads a bunch of monticello packages.
 
(0012054 - 1281 - 1525 - 1635 - 1635 - 1635 - 1635)
mberth
05-04-08 00:13

Some real delta debugging might be helpful (and interesting) here. For example, do a more systematic version of the following:

  Utilities updateFromServerThroughUpdateNumber: i.

  Transcript cr; show: '**** Benchmarking update through #' , SystemVersion
     current highestUpdate printString; cr.
  Preferences disable: #roundedWindowCorners.
  Transcript show: BrowserBenchmark browserIsQuick.
    
  Preferences enable: #roundedWindowCorners.
  Transcript show: BrowserBenchmark browserIsQuick.


Obstacles: BrowserBenchmark seems to get wiped out by the monticello installs - put it in another package. It gets really tiresome to hit "Proceed" everytime you get asked if you really want to install a new version of a package.

Then when you find an interesting change set you can narrow down even more by applying only part of it (or loading one monticello package after another, as some change sets are just monticcello loads).

As I wrote in an email to squeak-dev (Browsers slow in 3.9? Don't use rounded window corners.) browser slowdown is not an issue for me anymore in 3.9.1 - I use square corners as a workaround.

Delta debugging: http://www.st.cs.uni-sb.de/dd/ [^]

PS: I guess the screen damage rectangles are mostly OK for recent images (3.9.1)
 
(0012102 - 731 - 821 - 821 - 821 - 821 - 821)
wiz
05-17-08 04:07
edited on: 05-17-08 04:08

Comparisons

I had occasion to try debugging something in mvc. The response and performance seemed almost instantaneous compared with the morphic
responsiveness in the same image.

Why are MVC projects fast?

On the other hand I tried debugging some stuff in a squeak-dev image with pinesoft widgets and shout. Using it the same way as I would a regular morphic project. By the time I got to 15 or so windows/browsers open the whole thing had slown down to a standstill. I thought the image had died.

This was so bad as to make me realized speed/timing issues need some studies and some cures.

Why does pinesoft stuff on top of morphic stuff do that?

What is in the squeak-dev image that causes the slow down?

 

- Issue History
Date Modified Username Field Change
10-15-05 09:28 wiz New Issue
10-15-05 09:28 wiz File Added: SOURIN STARS.gif
10-19-05 18:09 Eddie Cottongim Note Added: 0002903
10-21-05 15:25 Eddie Cottongim Note Added: 0002948
10-24-05 08:04 wiz Note Added: 0002954
12-28-05 07:50 wiz Note Added: 0003394
12-28-05 11:07 pmm Issue Monitored: pmm
12-31-05 04:19 wiz Note Edited: 0003394
05-13-06 01:31 dway Note Added: 0004903
05-15-06 09:38 wiz Note Added: 0004922
05-20-06 08:43 wiz Note Added: 0005017
07-23-06 01:37 wiz Note Added: 0006164
10-09-07 03:04 matthewf Issue Monitored: matthewf
10-09-07 03:04 matthewf Relationship added child of 0006567
10-09-07 03:05 matthewf Category Browser => Morphic
05-01-08 19:00 wiz Relationship added child of 0006876
05-01-08 23:48 wiz File Added: 6680browben.text
05-01-08 23:55 wiz Note Added: 0012046
05-01-08 23:56 wiz File Added: changesforsq6685..6686
05-02-08 00:38 wiz Note Edited: 0012046
05-02-08 11:05 mberth File Added: BrowserBenchmark.st
05-02-08 11:12 mberth Note Added: 0012047
05-02-08 11:18 mberth Note Added: 0012048
05-02-08 13:35 mberth Issue Monitored: mberth
05-03-08 05:56 mberth Note Added: 0012050
05-03-08 23:07 wiz Note Added: 0012052
05-04-08 00:02 mberth Note Added: 0012053
05-04-08 00:13 mberth Note Added: 0012054
05-17-08 04:07 wiz Note Added: 0012102
05-17-08 04:08 wiz Note Edited: 0012102


Mantis 1.0.8[^]
Copyright © 2000 - 2007 Mantis Group
129 total queries executed.
66 unique queries executed.
Powered by Mantis Bugtracker