We'd recently installed a new report using RUN_REPORT at the client and the client complained that as the report progressed it became slower and slower and slower until it was taking minutes to print a line. When the report DID finally conclude it crashed with a SYS1000 error message.

We tested ourselves and sure enough the report was painful. We started it running against a couple of thousand records before going home for the night and by the time we came back in the morning it wasn't even half way through. When it did eventually finish it crashed! Still this last bit was something we were familiar with having already documented it in this blog posting. The slowdown on the otherhand was something else. So we did what most developers do in these circumstances and stripped the report back to bare bones and continued adding features in until it started misbehaving. The report had several BY clauses and several BREAK-ONs but it was when we came to the BREAK-ON modifier "'BP'" that problems started. Without this reports were produced at normal speed - with it they progressively got slower and slower.

Now much as we'd love to just throw the issue at Revelation, we know that the more information that we can provide, the more likely they are to be able to find a fix.Thus began several days of sleuthing. The first resort - as is our wont - was to install a profile file. This quickly grew to humongous proportions and we were faced with analysing a 3.6 GB profile log. Fortunately we have tools for this as regular readers will know, and pretty soon we were able to establish that the culprint seemed to be based around calls to get various printer object related properties.

Taking our investigations one step further we found that with every new line printed in the report an additional 700 GET/SET_PROPERTY calls were made.

To produce the first line of the report 5,324 calls were made
To produce the second line of the report 6,024 calls were made
To produce the third line of the report 6,724 calls were made

and by the time the 60th line of the report was reached GET/SET_PROPERTY was being called 40,000 times to print that one line! Using some additional tools we were able to establish what properties were being requested over and over again.

Armed with this information the stalwarts at Revelation were able to go off and discover a total variable not being cleared when the 'B' option was used. A patch was issued and once again we had RUN_Report. We did then run into another issue but we'll save that for another day!

Labels: profile, run_report