Re: Seeking understanding of my "gc cr multi block request" waits

From: Richard Piasecki <usenet2_at_ogoent.com>
Date: 19 Jul 2007 16:15:02 -0500
Message-ID: <rehv93pn7vdl2j88ismbt9mc5vn8d3i65u@4ax.com>

On Thu, 19 Jul 2007 16:23:03 -0000, K Gopalakrishnan <kaygopal_at_gmail.com> wrote:

>Rich,
>
>The problem with 'gc cr multiblock request' wait is, the wait is not
>complete till all the required blocks are read in to waiter's cache.
>This may take little longer time depending on the out come of the
>request (lock grant vs block tranfer).
>If you get the grant you can go ahead and read the blocks from the
>disk or you may get the blocks via wire if the blocks are cached
>somewhere in the global cache.
>
>If there is a buffer overflow (or some sort of werid issues like the
>bug you mentioned) you may see some blocks lost in transfer and that
>may take little longer than expected. BTW do you see any statistics
>mentioning blocks lost?
>You may want to check your UDP buffer settings..Also you may need to
>do a KCL tracing (or event 10708) to figure out what is happening
>undercovers. Another simple option is to check whether you have any
>'cr request retry' or 'cr request failure' events followed by the gc
>request.
>
>Coming back to your questions, your understanding about 'place holder'
>wait is correct. Also your expectation of the fixup waits (2way/3way)
>also correct. But due to bug 3423615, the fixup waits are not shown in
>the V$views.In short your assumptions 1 and 3 are correct. The above
>mentioned bug prevents showing the fixup waits in the views.
>
>BTW Do you care to send your raw trace file?
>
>-Gopal

I thank you, sir, for responding to my post and explaining what the "gc cr multi block request" waits are. I wasn't able to find bug #3423615 on Metalink. Are you sure that is the correct bug number? Also, on what process should I trace event 10708? I tried doing it in my session, but the trace file ended-up empty.

I was able to work with the developers at my company to re-write the query such that now it uses an index. I am hopeful that will eliminate the problem. I'll have to wait a few days to see if the problem (or another, different one) re-surfaces. I would still like to know, however, the reason for the extreme waits on this event, since I am sure it will happen again on a different query sometime down the road.

I have pasted the lines of the raw trace file that were generated during the wait to the bottom of this post. The trace file in question was generated when the query took about 20 seconds to run. All the waits were on the object number 51493 (the table being full scanned). The total amount of wait on "gc cr multi block request" was about 19.4 seconds. Interestingly, the vast majority of the wait time was generated during requests for 5 blocks. Block number 3710933 took about 6.8 seconds; block number 3710936 took about 4.2 seconds; block number 3710934 took about 3.8 seconds; block number 3710948 took about 3.6 seconds and block number 3710926 took about 0.8 seconds. All other waits combined were only about 0.2 seconds. There were four "cr request retry" waits (I don't know if that is good or bad). Looking at the waits in the trace file raises one big question in my mind: Why are there multiple waits for the same block, all consecutive? For example, block 3710933 (the one that took 6.8 seconds) had 11 consecutive "gc cr multi block request" waits. That's not the only one. Most of the blocks have multiple waits. I would have expected only one wait per block.

Obviously, I don't want you or anyone else doing my work for me, so I don't want you to spend too much time on this, but if you see anything significant in a quick perusal of this trace data, I would appreciate you enlightening me about it.

My compliments to you on a very well-written and informative book.

Rich

EXEC #17:c=0,e=315,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=1,tim=1156832996346541
WAIT #17: nam='gc cr multi block request' ela= 322 file#=4 block#=340074 class#=1 obj#=51493 tim=1156832996347737
WAIT #17: nam='gc cr multi block request' ela= 63 file#=4 block#=340074 class#=1 obj#=51493 tim=1156832996347923
WAIT #17: nam='gc cr block 2-way' ela= 470 p1=4 p2=340080 p3=1 obj#=51493 tim=1156832996348853
WAIT #17: nam='gc cr block 2-way' ela= 329 p1=4 p2=340082 p3=1 obj#=51493 tim=1156832996349396
WAIT #17: nam='gc cr multi block request' ela= 385 file#=4 block#=340088 class#=1 obj#=51493 tim=1156832996350160
WAIT #17: nam='gc cr multi block request' ela= 90 file#=4 block#=340088 class#=1 obj#=51493 tim=1156832996350352
WAIT #17: nam='gc cr multi block request' ela= 698 file#=4 block#=340104 class#=1 obj#=51493 tim=1156832996351380
WAIT #17: nam='gc cr multi block request' ela= 125 file#=4 block#=340104 class#=1 obj#=51493 tim=1156832996351591
WAIT #17: nam='gc cr multi block request' ela= 90 file#=4 block#=340104 class#=1 obj#=51493 tim=1156832996351772
WAIT #17: nam='gc cr multi block request' ela= 64 file#=4 block#=340104 class#=1 obj#=51493 tim=1156832996351894
WAIT #17: nam='gc cr multi block request' ela= 540 file#=4 block#=340880 class#=1 obj#=51493 tim=1156832996352995
WAIT #17: nam='gc cr multi block request' ela= 61 file#=4 block#=340880 class#=1 obj#=51493 tim=1156832996353157
WAIT #17: nam='gc cr multi block request' ela= 106 file#=4 block#=340880 class#=1 obj#=51493 tim=1156832996353326
WAIT #17: nam='gc cr multi block request' ela= 96 file#=4 block#=340880 class#=1 obj#=51493 tim=1156832996353512
WAIT #17: nam='gc cr multi block request' ela= 558 file#=4 block#=340896 class#=1 obj#=51493 tim=1156832996354602
WAIT #17: nam='gc cr multi block request' ela= 62 file#=4 block#=340896 class#=1 obj#=51493 tim=1156832996354759
WAIT #17: nam='gc cr multi block request' ela= 91 file#=4 block#=340894 class#=1 obj#=51493 tim=1156832996354913
WAIT #17: nam='gc cr multi block request' ela= 95 file#=4 block#=340894 class#=1 obj#=51493 tim=1156832996355079
WAIT #17: nam='gc cr multi block request' ela= 69 file#=4 block#=340894 class#=1 obj#=51493 tim=1156832996355213
WAIT #17: nam='gc cr multi block request' ela= 639 file#=4 block#=340904 class#=1 obj#=51493 tim=1156832996356381
WAIT #17: nam='gc cr multi block request' ela= 102 file#=4 block#=340904 class#=1 obj#=51493 tim=1156832996356569
WAIT #17: nam='gc cr multi block request' ela= 94 file#=4 block#=340904 class#=1 obj#=51493 tim=1156832996356730
WAIT #17: nam='gc cr multi block request' ela= 73 file#=4 block#=340904 class#=1 obj#=51493 tim=1156832996356862
WAIT #17: nam='gc cr multi block request' ela= 410 file#=4 block#=2169528 class#=1 obj#=51493 tim=1156832996357769
WAIT #17: nam='gc cr multi block request' ela= 125 file#=4 block#=2169528 class#=1 obj#=51493 tim=1156832996357991
WAIT #17: nam='gc cr multi block request' ela= 126 file#=4 block#=2169528 class#=1 obj#=51493 tim=1156832996358208
WAIT #17: nam='gc cr multi block request' ela= 38 file#=4 block#=2169528 class#=1 obj#=51493 tim=1156832996358311
WAIT #17: nam='gc cr multi block request' ela= 410 file#=4 block#=2275496 class#=1 obj#=51493 tim=1156832996359307
WAIT #17: nam='gc cr multi block request' ela= 138 file#=4 block#=2275496 class#=1 obj#=51493 tim=1156832996359538
WAIT #17: nam='gc cr multi block request' ela= 166 file#=4 block#=2275496 class#=1 obj#=51493 tim=1156832996359782
WAIT #17: nam='gc cr multi block request' ela= 423 file#=4 block#=2678232 class#=1 obj#=51493 tim=1156832996360904
WAIT #17: nam='gc cr multi block request' ela= 132 file#=4 block#=2678232 class#=1 obj#=51493 tim=1156832996361149
WAIT #17: nam='gc cr multi block request' ela= 108 file#=4 block#=2678232 class#=1 obj#=51493 tim=1156832996361352
WAIT #17: nam='gc cr multi block request' ela= 39 file#=4 block#=2678232 class#=1 obj#=51493 tim=1156832996361456
WAIT #17: nam='gc cr multi block request' ela= 412 file#=4 block#=2740120 class#=1 obj#=51493 tim=1156832996362391
WAIT #17: nam='gc cr multi block request' ela= 105 file#=4 block#=2740120 class#=1 obj#=51493 tim=1156832996362581
WAIT #17: nam='gc cr multi block request' ela= 120 file#=4 block#=2740120 class#=1 obj#=51493 tim=1156832996362770
WAIT #17: nam='gc cr multi block request' ela= 40 file#=4 block#=2740120 class#=1 obj#=51493 tim=1156832996362877
WAIT #17: nam='gc cr multi block request' ela= 436 file#=4 block#=2773384 class#=1 obj#=51493 tim=1156832996363811
WAIT #17: nam='gc cr multi block request' ela= 131 file#=4 block#=2773384 class#=1 obj#=51493 tim=1156832996364044
WAIT #17: nam='gc cr multi block request' ela= 107 file#=4 block#=2773384 class#=1 obj#=51493 tim=1156832996364249
WAIT #17: nam='gc cr multi block request' ela= 43 file#=4 block#=2773384 class#=1 obj#=51493 tim=1156832996364356
WAIT #17: nam='gc cr multi block request' ela= 611 file#=4 block#=3039352 class#=1 obj#=51493 tim=1156832996365495
WAIT #17: nam='gc cr multi block request' ela= 102 file#=4 block#=3039352 class#=1 obj#=51493 tim=1156832996365696
WAIT #17: nam='gc cr multi block request' ela= 101 file#=4 block#=3039352 class#=1 obj#=51493 tim=1156832996365871
WAIT #17: nam='gc cr multi block request' ela= 80 file#=4 block#=3039352 class#=1 obj#=51493 tim=1156832996366007
WAIT #17: nam='gc cr multi block request' ela= 635 file#=4 block#=3178440 class#=1 obj#=51493 tim=1156832996367167
WAIT #17: nam='gc cr multi block request' ela= 130 file#=4 block#=3178440 class#=1 obj#=51493 tim=1156832996367407
WAIT #17: nam='gc cr multi block request' ela= 151 file#=4 block#=3178440 class#=1 obj#=51493 tim=1156832996367678
WAIT #17: nam='gc cr multi block request' ela= 341 file#=4 block#=3710868 class#=1 obj#=51493 tim=1156832996368760
WAIT #17: nam='gc cr multi block request' ela= 185 file#=4 block#=3710868 class#=1 obj#=51493 tim=1156832996369059
WAIT #17: nam='gc cr multi block request' ela= 282 file#=4 block#=3710868 class#=1 obj#=51493 tim=1156832996369545
WAIT #17: nam='gc cr multi block request' ela= 404 file#=4 block#=3710885 class#=1 obj#=51493 tim=1156832996371232
WAIT #17: nam='gc cr multi block request' ela= 123 file#=4 block#=3710885 class#=1 obj#=51493 tim=1156832996371482
WAIT #17: nam='gc cr multi block request' ela= 140 file#=4 block#=3710885 class#=1 obj#=51493 tim=1156832996371725
WAIT #17: nam='gc cr multi block request' ela= 156 file#=4 block#=3710878 class#=1 obj#=51493 tim=1156832996371998
WAIT #17: nam='gc cr multi block request' ela= 164 file#=4 block#=3710878 class#=1 obj#=51493 tim=1156832996372252
WAIT #17: nam='gc cr multi block request' ela= 421 file#=4 block#=3710901 class#=1 obj#=51493 tim=1156832996373817
WAIT #17: nam='gc cr multi block request' ela= 129 file#=4 block#=3710901 class#=1 obj#=51493 tim=1156832996374060
WAIT #17: nam='gc cr multi block request' ela= 129 file#=4 block#=3710901 class#=1 obj#=51493 tim=1156832996374291
WAIT #17: nam='gc cr multi block request' ela= 170 file#=4 block#=3710901 class#=1 obj#=51493 tim=1156832996374543
WAIT #17: nam='gc cr multi block request' ela= 130 file#=4 block#=3710901 class#=1 obj#=51493 tim=1156832996374777
WAIT #17: nam='gc cr multi block request' ela= 70 file#=4 block#=3710901 class#=1 obj#=51493 tim=1156832996374914
WAIT #17: nam='gc cr multi block request' ela= 426 file#=4 block#=3710917 class#=1 obj#=51493 tim=1156832996376443
WAIT #17: nam='gc cr multi block request' ela= 154 file#=4 block#=3710917 class#=1 obj#=51493 tim=1156832996376727
WAIT #17: nam='gc cr multi block request' ela= 134 file#=4 block#=3710917 class#=1 obj#=51493 tim=1156832996376941
WAIT #17: nam='gc cr multi block request' ela= 122 file#=4 block#=3710917 class#=1 obj#=51493 tim=1156832996377137
WAIT #17: nam='gc cr multi block request' ela= 145 file#=4 block#=3710917 class#=1 obj#=51493 tim=1156832996377377
WAIT #17: nam='gc cr multi block request' ela= 64 file#=4 block#=3710910 class#=1 obj#=51493 tim=1156832996377521
WAIT #17: nam='gc cr multi block request' ela= 368 file#=4 block#=3710933 class#=1 obj#=51493 tim=1156832996379037
WAIT #17: nam='gc cr multi block request' ela= 103 file#=4 block#=3710933 class#=1 obj#=51493 tim=1156832996379262
WAIT #17: nam='gc cr multi block request' ela= 97 file#=4 block#=3710933 class#=1 obj#=51493 tim=1156832996379435
WAIT #17: nam='gc cr multi block request' ela= 183 file#=4 block#=3710933 class#=1 obj#=51493 tim=1156832996379702
WAIT #17: nam='gc cr multi block request' ela= 47 file#=4 block#=3710933 class#=1 obj#=51493 tim=1156832996379802
WAIT #17: nam='gc cr multi block request' ela= 1221996 file#=4 block#=3710933 class#=1 obj#=51493 tim=1156832997601849
WAIT #17: nam='gc cr multi block request' ela= 1221335 file#=4 block#=3710933 class#=1 obj#=51493 tim=1156832998823302
WAIT #17: nam='gc cr multi block request' ela= 1221405 file#=4 block#=3710933 class#=1 obj#=51493 tim=1156833000044803
WAIT #17: nam='gc cr multi block request' ela= 1221292 file#=4 block#=3710933 class#=1 obj#=51493 tim=1156833001266220
WAIT #17: nam='gc cr multi block request' ela= 1221330 file#=4 block#=3710933 class#=1 obj#=51493 tim=1156833002487673
WAIT #17: nam='gc cr multi block request' ela= 731794 file#=4 block#=3710933 class#=1 obj#=51493 tim=1156833003219593
WAIT #17: nam='cr request retry' ela= 12 file#=4 block#=3710918 p3=0 obj#=51493 tim=1156833003228119
WAIT #17: nam='gc cr multi block request' ela= 403 file#=4 block#=3710934 class#=1 obj#=51493 tim=1156833003229296
WAIT #17: nam='gc cr multi block request' ela= 224 file#=4 block#=3710934 class#=1 obj#=51493 tim=1156833003229688
WAIT #17: nam='gc cr multi block request' ela= 85 file#=4 block#=3710934 class#=1 obj#=51493 tim=1156833003229925
WAIT #17: nam='gc cr multi block request' ela= 80 file#=4 block#=3710934 class#=1 obj#=51493 tim=1156833003244590
WAIT #17: nam='gc cr multi block request' ela= 1221205 file#=4 block#=3710934 class#=1 obj#=51493 tim=1156833004465899
WAIT #17: nam='gc cr multi block request' ela= 1221251 file#=4 block#=3710934 class#=1 obj#=51493 tim=1156833005687268

*** 2007-07-16 10:43:19.074

WAIT #17: nam='gc cr multi block request' ela= 1221346 file#=4 block#=3710934 class#=1 obj#=51493 tim=1156833006908722
WAIT #17: nam='gc cr multi block request' ela= 157480 file#=4 block#=3710934 class#=1 obj#=51493 tim=1156833007066356
WAIT #17: nam='cr request retry' ela= 9 file#=4 block#=3710919 p3=0 obj#=51493 tim=1156833007074409
WAIT #17: nam='gc cr multi block request' ela= 395 file#=4 block#=3710936 class#=1 obj#=51493 tim=1156833007075357
WAIT #17: nam='gc cr multi block request' ela= 73 file#=4 block#=3710936 class#=1 obj#=51493 tim=1156833007075512
WAIT #17: nam='gc cr multi block request' ela= 82 file#=4 block#=3710936 class#=1 obj#=51493 tim=1156833007075660
WAIT #17: nam='gc cr multi block request' ela= 65 file#=4 block#=3710936 class#=1 obj#=51493 tim=1156833007075802
WAIT #17: nam='gc cr multi block request' ela= 51 file#=4 block#=3710936 class#=1 obj#=51493 tim=1156833007075901
WAIT #17: nam='gc cr multi block request' ela= 1221207 file#=4 block#=3710936 class#=1 obj#=51493 tim=1156833008297165
WAIT #17: nam='gc cr multi block request' ela= 1221333 file#=4 block#=3710936 class#=1 obj#=51493 tim=1156833009518611
WAIT #17: nam='gc cr multi block request' ela= 1221324 file#=4 block#=3710936 class#=1 obj#=51493 tim=1156833010740057
WAIT #17: nam='gc cr multi block request' ela= 581698 file#=4 block#=3710936 class#=1 obj#=51493 tim=1156833011321856
WAIT #17: nam='gc cr multi block request' ela= 846994 file#=4 block#=3710926 class#=1 obj#=51493 tim=1156833012177298
WAIT #17: nam='cr request retry' ela= 7 file#=4 block#=3710921 p3=0 obj#=51493 tim=1156833012177515
WAIT #17: nam='gc cr multi block request' ela= 420 file#=4 block#=3710936 class#=1 obj#=51493 tim=1156833012178381
WAIT #17: nam='gc cr multi block request' ela= 156 file#=4 block#=3710930 class#=1 obj#=51493 tim=1156833012178666
WAIT #17: nam='gc cr multi block request' ela= 143 file#=4 block#=3710926 class#=1 obj#=51493 tim=1156833012178925
WAIT #17: nam='db file parallel read' ela= 31637 files=1 blocks=9 requests=9 obj#=51493 tim=1156833012210685
WAIT #17: nam='gc cr multi block request' ela= 347 file#=4 block#=3710952 class#=1 obj#=51493 tim=1156833012212123
WAIT #17: nam='gc cr multi block request' ela= 178 file#=4 block#=3710952 class#=1 obj#=51493 tim=1156833012212449
WAIT #17: nam='gc cr multi block request' ela= 161 file#=4 block#=3710952 class#=1 obj#=51493 tim=1156833012212736
WAIT #17: nam='gc cr multi block request' ela= 140 file#=4 block#=3710952 class#=1 obj#=51493 tim=1156833012212998
WAIT #17: nam='gc cr multi block request' ela= 1222017 file#=4 block#=3710948 class#=1 obj#=51493 tim=1156833013435124
WAIT #17: nam='gc cr multi block request' ela= 1222067 file#=4 block#=3710948 class#=1 obj#=51493 tim=1156833014657286
WAIT #17: nam='gc cr multi block request' ela= 1186950 file#=4 block#=3710948 class#=1 obj#=51493 tim=1156833015844349
WAIT #17: nam='gc cr multi block request' ela= 21 file#=4 block#=3710941 class#=1 obj#=51493 tim=1156833015852970
WAIT #17: nam='cr request retry' ela= 5 file#=4 block#=3710937 p3=0 obj#=51493 tim=1156833015853138
WAIT #17: nam='gc cr multi block request' ela= 384 file#=4 block#=3710952 class#=1 obj#=51493 tim=1156833015854114
WAIT #17: nam='gc cr multi block request' ela= 82 file#=4 block#=3710952 class#=1 obj#=51493 tim=1156833015854289
WAIT #17: nam='gc cr multi block request' ela= 86 file#=4 block#=3710952 class#=1 obj#=51493 tim=1156833015854451
WAIT #17: nam='gc cr multi block request' ela= 101 file#=4 block#=3710952 class#=1 obj#=51493 tim=1156833015854612
WAIT #17: nam='gc cr multi block request' ela= 76 file#=4 block#=3710952 class#=1 obj#=51493 tim=1156833015854751
WAIT #17: nam='gc cr multi block request' ela= 71 file#=4 block#=3710952 class#=1 obj#=51493 tim=1156833015854877
WAIT #17: nam='gc cr multi block request' ela= 414 file#=4 block#=3710942 class#=1 obj#=51493 tim=1156833015855381
WAIT #17: nam='db file scattered read' ela= 13680 file#=4 block#=3710937 blocks=3 obj#=51493 tim=1156833015869140
WAIT #17: nam='gc cr multi block request' ela= 563 file#=4 block#=3710955 class#=1 obj#=51493 tim=1156833015870140
WAIT #17: nam='gc cr multi block request' ela= 185 file#=4 block#=3710955 class#=1 obj#=51493 tim=1156833015870431
WAIT #17: nam='gc cr multi block request' ela= 47 file#=4 block#=3710955 class#=1 obj#=51493 tim=1156833015870541
WAIT #17: nam='gc cr multi block request' ela= 44 file#=4 block#=3710955 class#=1 obj#=51493 tim=1156833015870632
WAIT #17: nam='gc cr multi block request' ela= 44 file#=4 block#=3710955 class#=1 obj#=51493 tim=1156833015870722
WAIT #17: nam='gc cr multi block request' ela= 42 file#=4 block#=3710955 class#=1 obj#=51493 tim=1156833015870811
WAIT #17: nam='gc cr multi block request' ela= 48 file#=4 block#=3710955 class#=1 obj#=51493 tim=1156833015870906
WAIT #17: nam='gc cr multi block request' ela= 52 file#=4 block#=3710955 class#=1 obj#=51493 tim=1156833015871005
WAIT #17: nam='gc cr multi block request' ela= 42 file#=4 block#=3710955 class#=1 obj#=51493 tim=1156833015871093
WAIT #17: nam='gc cr multi block request' ela= 48 file#=4 block#=3710955 class#=1 obj#=51493 tim=1156833015871187
WAIT #17: nam='gc cr multi block request' ela= 41 file#=4 block#=3710955 class#=1 obj#=51493 tim=1156833015871274
WAIT #17: nam='gc cr multi block request' ela= 41 file#=4 block#=3710955 class#=1 obj#=51493 tim=1156833015871360
WAIT #17: nam='gc cr multi block request' ela= 48 file#=4 block#=3710955 class#=1 obj#=51493 tim=1156833015871469
WAIT #17: nam='db file parallel read' ela= 916 files=1 blocks=3 requests=3 obj#=51493 tim=1156833015872455
WAIT #17: nam='gc cr multi block request' ela= 491 file#=4 block#=3710970 class#=1 obj#=51493 tim=1156833015873791
WAIT #17: nam='gc cr multi block request' ela= 54 file#=4 block#=3710970 class#=1 obj#=51493 tim=1156833015873931
WAIT #17: nam='gc cr multi block request' ela= 55 file#=4 block#=3710970 class#=1 obj#=51493 tim=1156833015874033
WAIT #17: nam='gc cr multi block request' ela= 88 file#=4 block#=3710970 class#=1 obj#=51493 tim=1156833015874169
WAIT #17: nam='gc cr multi block request' ela= 48 file#=4 block#=3710970 class#=1 obj#=51493 tim=1156833015874265
WAIT #17: nam='gc cr multi block request' ela= 43 file#=4 block#=3710970 class#=1 obj#=51493 tim=1156833015874353
WAIT #17: nam='gc cr multi block request' ela= 44 file#=4 block#=3710970 class#=1 obj#=51493 tim=1156833015874443
WAIT #17: nam='gc cr multi block request' ela= 73 file#=4 block#=3710970 class#=1 obj#=51493 tim=1156833015874562
WAIT #17: nam='gc cr multi block request' ela= 42 file#=4 block#=3710970 class#=1 obj#=51493 tim=1156833015874659
WAIT #17: nam='gc cr multi block request' ela= 43 file#=4 block#=3710970 class#=1 obj#=51493 tim=1156833015874747
WAIT #17: nam='gc cr multi block request' ela= 50 file#=4 block#=3710970 class#=1 obj#=51493 tim=1156833015874843
WAIT #17: nam='gc cr multi block request' ela= 52 file#=4 block#=3710970 class#=1 obj#=51493 tim=1156833015874941
WAIT #17: nam='gc cr multi block request' ela= 45 file#=4 block#=3710970 class#=1 obj#=51493 tim=1156833015875034
WAIT #17: nam='gc cr multi block request' ela= 68 file#=4 block#=3710970 class#=1 obj#=51493 tim=1156833015875168

FETCH #17:c=75989,e=19529402,p=15,cr=235,cu=0,mis=0,r=1,dep=2,og=1,tim=1156833015875977 Received on Thu Jul 19 2007 - 16:15:02 CDT