Mysterious "progressive slowing" problem in run loop / drawRect

Question

Here's a real mystery.

Imagine you are doing the conventional process of drawing a complex image offscreen (CGLayer), and you are updating the image on to the screen intermittently as you draw.

As you know the way to do this is: run the large drawing process in the background, and call to the foreground for setNeedsDisplays as desired, causing the image to be updated. This is trivial and achieved with two lines of code.

However, when you do this, there is a mysterious problem: the time taken for each drawing cycle, increases each time, becoming unusable. Further, the time can vary erratically.

Is this a known iOS bug, or? Has anyone seen this before?

Here is an extremely trivial, extremely easy to understand app, that demos the problem:

http://www.fileswap.com/dl/p8lU3gAi/stepwiseDrawingV2.zip.html

Output example below.

Does anyone know why this happens? It is very strange behaviour from the OS.

Later ... an astounding work-around has been figured out by FELZ. Felz copies the CGLayer once each round. This completely stops the strange behaviour.

However there is still no really clear understanding of what the heck exactly was happening: hence literally, where is the time being used when the bizarre problem exhibits?

And here's a long example of the output ...

Notice you sometimes get a "doubly bizarre" result like the following: It is exhibiting the "normal" bizarre behavior: the time increases each go around. However, occasionally the time will drop to "incredibly quick" for a couple rounds, and then return. Weird huh? Further, if you are running on your simulator, click back and fore quickly to unrelated apps on your Mac for "even weirder" results.

Although Felz has given a perfect working answer, the actual mechanism is still a mystery.

:26:56.697 stepwiseDrawing[5334:1a03] time difference was     0
:26:56.707 stepwiseDrawing[5334:1a03] time difference was    10
:26:56.717 stepwiseDrawing[5334:1a03] time difference was    10
:26:56.744 stepwiseDrawing[5334:1a03] time difference was    27
:26:56.771 stepwiseDrawing[5334:1a03] time difference was    27
:26:56.807 stepwiseDrawing[5334:1a03] time difference was    37
:26:56.829 stepwiseDrawing[5334:1a03] time difference was    22
:26:56.864 stepwiseDrawing[5334:1a03] time difference was    35
:26:56.891 stepwiseDrawing[5334:1a03] time difference was    28
:26:56.936 stepwiseDrawing[5334:1a03] time difference was    45
:26:56.949 stepwiseDrawing[5334:1a03] time difference was    12
:26:56.981 stepwiseDrawing[5334:1a03] time difference was    32
:26:57.008 stepwiseDrawing[5334:1a03] time difference was    27
:26:57.041 stepwiseDrawing[5334:1a03] time difference was    33
:26:57.074 stepwiseDrawing[5334:1a03] time difference was    34
:26:57.109 stepwiseDrawing[5334:1a03] time difference was    34
:26:57.143 stepwiseDrawing[5334:1a03] time difference was    35
:26:57.179 stepwiseDrawing[5334:1a03] time difference was    36
:26:57.220 stepwiseDrawing[5334:1a03] time difference was    42
:26:57.271 stepwiseDrawing[5334:1a03] time difference was    51
:26:57.312 stepwiseDrawing[5334:1a03] time difference was    40
:26:57.356 stepwiseDrawing[5334:1a03] time difference was    45
:26:57.400 stepwiseDrawing[5334:1a03] time difference was    44
:26:57.447 stepwiseDrawing[5334:1a03] time difference was    46
:26:57.493 stepwiseDrawing[5334:1a03] time difference was    46
:26:57.542 stepwiseDrawing[5334:1a03] time difference was    49
:26:57.593 stepwiseDrawing[5334:1a03] time difference was    50
:26:57.707 stepwiseDrawing[5334:1a03] time difference was   114
:26:57.766 stepwiseDrawing[5334:1a03] time difference was    58
:26:57.801 stepwiseDrawing[5334:1a03] time difference was    36
:26:57.856 stepwiseDrawing[5334:1a03] time difference was    55
:26:57.918 stepwiseDrawing[5334:1a03] time difference was    62
:26:57.976 stepwiseDrawing[5334:1a03] time difference was    58
:26:58.039 stepwiseDrawing[5334:1a03] time difference was    62
:26:58.101 stepwiseDrawing[5334:1a03] time difference was    63
:26:58.165 stepwiseDrawing[5334:1a03] time difference was    63
:26:58.229 stepwiseDrawing[5334:1a03] time difference was    64
:26:58.294 stepwiseDrawing[5334:1a03] time difference was    66
:26:58.365 stepwiseDrawing[5334:1a03] time difference was    70
:26:58.436 stepwiseDrawing[5334:1a03] time difference was    72
:26:58.507 stepwiseDrawing[5334:1a03] time difference was    70
:26:58.572 stepwiseDrawing[5334:1a03] time difference was    65
:26:58.652 stepwiseDrawing[5334:1a03] time difference was    81
:26:58.726 stepwiseDrawing[5334:1a03] time difference was    74
:26:58.809 stepwiseDrawing[5334:1a03] time difference was    82
:26:58.879 stepwiseDrawing[5334:1a03] time difference was    70
:26:58.965 stepwiseDrawing[5334:1a03] time difference was    87
:26:59.043 stepwiseDrawing[5334:1a03] time difference was    77
:26:59.126 stepwiseDrawing[5334:1a03] time difference was    83
:26:59.210 stepwiseDrawing[5334:1a03] time difference was    84
:26:59.215 stepwiseDrawing[5334:1a03] time difference was     6
:26:59.310 stepwiseDrawing[5334:1a03] time difference was    95
:26:59.397 stepwiseDrawing[5334:1a03] time difference was    87
:26:59.486 stepwiseDrawing[5334:1a03] time difference was    89
:26:59.577 stepwiseDrawing[5334:1a03] time difference was    91
:26:59.668 stepwiseDrawing[5334:1a03] time difference was    91
:26:59.768 stepwiseDrawing[5334:1a03] time difference was   100
:26:59.856 stepwiseDrawing[5334:1a03] time difference was    88
:26:59.857 stepwiseDrawing[5334:1a03] time difference was     1
:26:59.965 stepwiseDrawing[5334:1a03] time difference was   108
:27:00.064 stepwiseDrawing[5334:1a03] time difference was   100
:27:00.165 stepwiseDrawing[5334:1a03] time difference was   101
:27:00.268 stepwiseDrawing[5334:1a03] time difference was   103
:27:00.371 stepwiseDrawing[5334:1a03] time difference was   103
:27:00.377 stepwiseDrawing[5334:1a03] time difference was     7
:27:00.493 stepwiseDrawing[5334:1a03] time difference was   115
:27:00.601 stepwiseDrawing[5334:1a03] time difference was   108
:27:00.710 stepwiseDrawing[5334:1a03] time difference was   109
:27:00.820 stepwiseDrawing[5334:1a03] time difference was   111
:27:00.939 stepwiseDrawing[5334:1a03] time difference was   119
:27:01.053 stepwiseDrawing[5334:1a03] time difference was   114
:27:01.162 stepwiseDrawing[5334:1a03] time difference was   108
:27:01.278 stepwiseDrawing[5334:1a03] time difference was   116
:27:01.396 stepwiseDrawing[5334:1a03] time difference was   118
:27:01.515 stepwiseDrawing[5334:1a03] time difference was   119
:27:01.637 stepwiseDrawing[5334:1a03] time difference was   122
:27:01.648 stepwiseDrawing[5334:1a03] time difference was    11
:27:01.769 stepwiseDrawing[5334:1a03] time difference was   121
:27:01.775 stepwiseDrawing[5334:1a03] time difference was     6
:27:01.910 stepwiseDrawing[5334:1a03] time difference was   135
:27:01.911 stepwiseDrawing[5334:1a03] time difference was     1
:27:02.045 stepwiseDrawing[5334:1a03] time difference was   134
:27:02.175 stepwiseDrawing[5334:1a03] time difference was   131
:27:02.314 stepwiseDrawing[5334:1a03] time difference was   139
:27:02.441 stepwiseDrawing[5334:1a03] time difference was   127
:27:02.586 stepwiseDrawing[5334:1a03] time difference was   145
:27:02.715 stepwiseDrawing[5334:1a03] time difference was   129
:27:02.853 stepwiseDrawing[5334:1a03] time difference was   138
:27:03.000 stepwiseDrawing[5334:1a03] time difference was   146
:27:03.133 stepwiseDrawing[5334:1a03] time difference was   134
:27:03.276 stepwiseDrawing[5334:1a03] time difference was   142
:27:03.419 stepwiseDrawing[5334:1a03] time difference was   143
:27:03.564 stepwiseDrawing[5334:1a03] time difference was   145
:27:03.717 stepwiseDrawing[5334:1a03] time difference was   153
:27:03.858 stepwiseDrawing[5334:1a03] time difference was   141
:27:04.008 stepwiseDrawing[5334:1a03] time difference was   149
:27:04.159 stepwiseDrawing[5334:1a03] time difference was   151
:27:04.318 stepwiseDrawing[5334:1a03] time difference was   159
:27:04.471 stepwiseDrawing[5334:1a03] time difference was   153
:27:04.620 stepwiseDrawing[5334:1a03] time difference was   149
:27:04.778 stepwiseDrawing[5334:1a03] time difference was   158
:27:04.939 stepwiseDrawing[5334:1a03] time difference was   161
:27:05.098 stepwiseDrawing[5334:1a03] time difference was   160
:27:05.269 stepwiseDrawing[5334:1a03] time difference was   171
:27:05.433 stepwiseDrawing[5334:1a03] time difference was   164
:27:05.600 stepwiseDrawing[5334:1a03] time difference was   166
:27:05.765 stepwiseDrawing[5334:1a03] time difference was   165
:27:05.932 stepwiseDrawing[5334:1a03] time difference was   167
:27:06.107 stepwiseDrawing[5334:1a03] time difference was   175
:27:06.269 stepwiseDrawing[5334:1a03] time difference was   163
:27:06.441 stepwiseDrawing[5334:1a03] time difference was   171
:27:06.617 stepwiseDrawing[5334:1a03] time difference was   176
:27:06.798 stepwiseDrawing[5334:1a03] time difference was   181
:27:06.971 stepwiseDrawing[5334:1a03] time difference was   173
:27:07.154 stepwiseDrawing[5334:1a03] time difference was   183
:27:07.326 stepwiseDrawing[5334:1a03] time difference was   172
:27:07.513 stepwiseDrawing[5334:1a03] time difference was   187
:27:07.689 stepwiseDrawing[5334:1a03] time difference was   176
:27:07.875 stepwiseDrawing[5334:1a03] time difference was   185
:27:08.059 stepwiseDrawing[5334:1a03] time difference was   184
:27:08.251 stepwiseDrawing[5334:1a03] time difference was   192
:27:08.432 stepwiseDrawing[5334:1a03] time difference was   181
:27:08.620 stepwiseDrawing[5334:1a03] time difference was   188
:27:08.811 stepwiseDrawing[5334:1a03] time difference was   190
:27:09.004 stepwiseDrawing[5334:1a03] time difference was   193
:27:09.195 stepwiseDrawing[5334:1a03] time difference was   191
:27:09.393 stepwiseDrawing[5334:1a03] time difference was   198
:27:09.590 stepwiseDrawing[5334:1a03] time difference was   197
:27:09.795 stepwiseDrawing[5334:1a03] time difference was   205
:27:09.989 stepwiseDrawing[5334:1a03] time difference was   193
:27:10.189 stepwiseDrawing[5334:1a03] time difference was   200
:27:10.392 stepwiseDrawing[5334:1a03] time difference was   203
:27:10.600 stepwiseDrawing[5334:1a03] time difference was   208
:27:10.801 stepwiseDrawing[5334:1a03] time difference was   202
:27:11.006 stepwiseDrawing[5334:1a03] time difference was   205
:27:11.220 stepwiseDrawing[5334:1a03] time difference was   213
:27:11.430 stepwiseDrawing[5334:1a03] time difference was   210
:27:11.633 stepwiseDrawing[5334:1a03] time difference was   203
:27:11.843 stepwiseDrawing[5334:1a03] time difference was   210
:27:12.055 stepwiseDrawing[5334:1a03] time difference was   213
:27:12.276 stepwiseDrawing[5334:1a03] time difference was   220
:27:12.484 stepwiseDrawing[5334:1a03] time difference was   208
:27:12.700 stepwiseDrawing[5334:1a03] time difference was   216
:27:12.919 stepwiseDrawing[5334:1a03] time difference was   219
:27:13.145 stepwiseDrawing[5334:1a03] time difference was   226
:27:13.360 stepwiseDrawing[5334:1a03] time difference was   215
:27:13.584 stepwiseDrawing[5334:1a03] time difference was   224
:27:13.813 stepwiseDrawing[5334:1a03] time difference was   229
:27:14.049 stepwiseDrawing[5334:1a03] time difference was   236
:27:14.269 stepwiseDrawing[5334:1a03] time difference was   220
:27:14.496 stepwiseDrawing[5334:1a03] time difference was   228
:27:14.725 stepwiseDrawing[5334:1a03] time difference was   229
:27:14.963 stepwiseDrawing[5334:1a03] time difference was   238
:27:15.196 stepwiseDrawing[5334:1a03] time difference was   232
:27:15.423 stepwiseDrawing[5334:1a03] time difference was   227
:27:15.657 stepwiseDrawing[5334:1a03] time difference was   235
:27:15.901 stepwiseDrawing[5334:1a03] time difference was   243
:27:16.133 stepwiseDrawing[5334:1a03] time difference was   232
:27:16.372 stepwiseDrawing[5334:1a03] time difference was   240
:27:16.613 stepwiseDrawing[5334:1a03] time difference was   241
:27:16.863 stepwiseDrawing[5334:1a03] time difference was   250
:27:17.101 stepwiseDrawing[5334:1a03] time difference was   238
:27:17.346 stepwiseDrawing[5334:1a03] time difference was   245
:27:17.593 stepwiseDrawing[5334:1a03] time difference was   247
:27:17.849 stepwiseDrawing[5334:1a03] time difference was   256
:27:18.093 stepwiseDrawing[5334:1a03] time difference was   244
:27:18.344 stepwiseDrawing[5334:1a03] time difference was   251
:27:18.603 stepwiseDrawing[5334:1a03] time difference was   260
:27:18.854 stepwiseDrawing[5334:1a03] time difference was   251
:27:19.114 stepwiseDrawing[5334:1a03] time difference was   259
:27:19.376 stepwiseDrawing[5334:1a03] time difference was   263
:27:19.646 stepwiseDrawing[5334:1a03] time difference was   270
:27:19.927 stepwiseDrawing[5334:1a03] time difference was   281
:27:20.202 stepwiseDrawing[5334:1a03] time difference was   274
:27:20.460 stepwiseDrawing[5334:1a03] time difference was   259
:27:20.743 stepwiseDrawing[5334:1a03] time difference was   283
:27:21.011 stepwiseDrawing[5334:1a03] time difference was   268
:27:21.281 stepwiseDrawing[5334:1a03] time difference was   270
:27:21.563 stepwiseDrawing[5334:1a03] time difference was   282
:27:21.848 stepwiseDrawing[5334:1a03] time difference was   284
:27:22.126 stepwiseDrawing[5334:1a03] time difference was   278
:27:22.398 stepwiseDrawing[5334:1a03] time difference was   272
:27:22.677 stepwiseDrawing[5334:1a03] time difference was   279
:27:22.970 stepwiseDrawing[5334:1a03] time difference was   293
:27:23.258 stepwiseDrawing[5334:1a03] time difference was   288
:27:23.545 stepwiseDrawing[5334:1a03] time difference was   287
:27:23.834 stepwiseDrawing[5334:1a03] time difference was   289
:27:24.122 stepwiseDrawing[5334:1a03] time difference was   288
:27:24.413 stepwiseDrawing[5334:1a03] time difference was   292
:27:24.708 stepwiseDrawing[5334:1a03] time difference was   295
:27:25.002 stepwiseDrawing[5334:1a03] time difference was   294
:27:25.303 stepwiseDrawing[5334:1a03] time difference was   301
:27:25.585 stepwiseDrawing[5334:1a03] time difference was   282
:27:25.880 stepwiseDrawing[5334:1a03] time difference was   294
:27:26.174 stepwiseDrawing[5334:1a03] time difference was   294
:27:26.470 stepwiseDrawing[5334:1a03] time difference was   296
:27:26.475 stepwiseDrawing[5334:1a03] time difference was     5
:27:26.777 stepwiseDrawing[5334:1a03] time difference was   302
:27:27.077 stepwiseDrawing[5334:1a03] time difference was   299
:27:27.373 stepwiseDrawing[5334:1a03] time difference was   297

Autotoxin

What's different in V2 of your code? – Crematory

I'd just like to point out that using drawRect: on iOS is a really inefficient way to do drawing. – Hyperbolic

Answer 1

First let me say this was an interesting puzzle. I had a lot of fun working on this one. Nice question and nice sample code.

Here is my take on a possible answer:

The issue I see is the following. CGLayer are great for repeatedly painting because they cache their rendering into a flat image. The cache is invalidated when additional operations are appended to the context. When this happens, the CGLayer is rendered again. The slowdown is cause because the code maintains a single CGLayer (offscreenPrefabCGL) that has its context modified in every iteration of the loop in paintActualGutsOfHugeImage. Because the sequence of operations in offscreenPrefabCGL's context grows with each flower, each render takes more time. This explains the increase in time for each display.

I see two solutions:

1. Clip the new rendering into a particular in the PaintView. Instead of invalidating the complete view, invalidate only the the CGRect that really needs repainting. This, as I understand it, is the solution proposed by @v01d.
2. Flatten the layer. Instead of holding a single CGLayer, copy the CGLayer on each iteration. This maintains a flat image in the Layer that is very fast to render.

I Implemented (2) with good results. The first 100 flowers are faster and then it will stabilize in 120ms (in Device). I tested my modified version with up to 2000 flowers.

My modified version is in:

http://dl.dropbox.com/u/9866261/felz_mod_stepwiseDrawingV2.zip

Fosterfosterage

Yep that's it, see EDIT2 I posted just a little while ago. – Knowing

Felz, your solution of copying the CGLayer is astounding!!!! You rock! Let me challenge you both further ... in fact WHY DOES it show the unusual behavior, if you do not copy it each time? – Autotoxin

Hey Joe (<- Hendrix reference?) I agree there is more to the problem. I had the same expectation as you have, that rendering the the CGLayer with the extra flower would be an O(1) operation. Evidence points to the O(n) explanation and this is unexpected. I can't really find anything in the CGLayer documentation that can explain this. I'm badly curious as well!! any apple engineer reading this that can spear some details on the CGLayer inner-works? – Fosterfosterage

The reason it's O(n) might be that the CGLayer context is nil, meaning there's nothing to draw into to flatten the bits to O(n). This can be fixed by first assigning a reasonable sized bitmap to the layer context before any drawing. – Crematory

Another possible reason is that the copy operation creates a double buffered pair of contexts, allowing you to draw into one while the other is being rendered for display. How could this hypothesis be tested? – Crematory

The link to the working solution from Felz is giving me a 404 message. Would be awesome if he could update his link. – Schooling

fixed the link. Sorry about that: dropbox cleaning gone bad. – Fosterfosterage

Answer 2

EDIT2:

Here's a working (no slowdown) debug project: http://bit.ly/eukSgR

This project is by no means optimal.

What is interesting here is the need of a bitmap context. A CGLayer caches your image draws and causes your progressive slowdown. With a bitmap context it is forced to render; and then you are simply pushing those pixels to the UIView's CALayer in drawRect:.

I guess to get more speed, you can use setNeedsDisplayInRect: to minimise the area to redraw.

But, other than maybe an optimisation or two here and there, pushing pixels through a UIView will always be slower than doing this on the GPU completely via say GL.

Knowing

Hi void, thanks very much for checking the demo. Your comment about NSLog appears to be totally incorrect. Simply remove the NSLog, and you will easily see the same strange behaviour on-screen. – Autotoxin

Yep that's exactly what it's doing. You call setNeedsDisplay faster than it can put it on the screen; the OS banks it up till it can catch up (which is when you finish painting). – Knowing

Repainting nil still requires 1024x768 pixels to be moved on screen. They are invalidated by calling setNeedsDisplay. – Knowing

The 300ms you are getting is perfectly normal. This equates to about 3.3 frames per second. Considering what you are asking of the iPad I think this is quite good. – Knowing

Yes on that sudden jump from 300ms down to nearly nothing... I think that is simply the screen refresh syncing up with your drawing routine. – Knowing

Even though you are painting the same CGLayer every drawRect the pixels have changed, and you ask the OS to paint the whole thing. Also note you are modifying the layer in a background thread whilst asking the OS to paint it. This is obviously going to be a stall. – Knowing

Hi Void, it is not producing 300 ms .. it starts very low (1 or 2 ms, as one would expect -- CGLayers, even full screen, are handled by the graphics chipset at blazing speeds) and (bizarrely) becomes slightly longer each time. Please note, simply set it to keep looping for 1000s of times rather than 100, and you will see it just continuously gets longer and longer! (other than the "random jumps" to different values which you may see). The only reason I mentioned 300 is that in that one example in particular it jumped to "300" at one stage. – Autotoxin

These comments are turning into a forum. :) I'm interested enough to play with some example projects in Xcode. I'll get back to you with what I find. – Knowing

Yeah, but bare in mind without that NSLog things move loads faster. I recommend turning your NSLog into a UILabel or print it to your CGLayer. It will have far less impact on what you're measuring. – Knowing

I've updated my answer with a working project to fix your issue. The problem is the CGLayer is not necessarily drawing anything, and building up lots of uncached renders. – Knowing

Hi Void, that's an ingenious workaround, avoiding the use of CGLayer and using bitmaps instead. Great example code you posted for future readers. – Autotoxin

Answer 3

As one experiment, I suggest you update your animated progress view without trying to draw with or read from the unfinished large image bitmap or layer drawing in progress. Reading from or drawing with an unfinished compositing to another drawing context may be doing interesting things to the GPU pipeline or drawing state. Try drawing something else in your pepper method. A simple counter or something.

Crematory