iphone - 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

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