How often is v$sys_time_model updated? July 14, 2010
Posted by mwidlake in internals, performance.Tags: data dictionary, performance
6 comments
I think this posting might go down as one of my more pointless contributions to the Oracle knowledge sphere 🙂
I was looking at V$SYS_TIME_MODEL and V$SESS_TIME_MODEL and I just happened to run “select * from V$SYS_TIME_MODEL” several times in very quick succession. And I noticed the values for the various counters stayed the same between a couple of the runs.
“Hmmm, interesting” I thought “The values are only flushed down to the view ‘periodically’. I wonder how periodically?”… and thus I wasted a lunch time.
I used the below sql*plus-PL/SQL script to investigate the refreshing of v$sess_time_model. Yes, I know the title says v$sys_time_model but the numbers are smaller and easier to check for the session version of the view and they are virtually the same, I can bet on the results being very similar. This is my script (and it is on 10.2.0.3 on linux):
--test_vstm_upd
-- how often is v$sessstat updated
set trims on
set term off
set serveroutput on size unli
spool test_vstm_upd
begin
for a in 1..1000 loop
for vrec in
(select rpad(rpad(to_char(a),4)||' '||to_char(systimestamp,'ss.ff')||' '|| stat_name||' ',45)||value rec
from v$sess_time_model
-- replace with your current session ID
where sid=1989
and stat_id in (3649082374,2748282437,2821698184,2643905994)
)
loop
dbms_output.put_line(vrec.rec);
end loop;
dbms_output.put_line(chr(9));
end loop;
end;
/
set term on
spool off
As you can see, it simply loops around selecting four of the values from v$sess_time_model, including the loop counter and current timestamp. Timetamp is evaluated afresh for each executed sql statement.
Here is the output for the first three iterations;
1 53.389576 DB time 475860419 1 53.389576 DB CPU 402642660 1 53.389576 sql execute elapsed time 209780319 1 53.389576 PL/SQL execution elapsed time 52290858 2 53.408944 DB time 475860419 2 53.408944 DB CPU 402642660 2 53.408944 sql execute elapsed time 209780319 2 53.408944 PL/SQL execution elapsed time 52290858 3 53.429159 DB time 475860419 3 53.429159 DB CPU 402642660 3 53.429159 sql execute elapsed time 209780319 3 53.429159 PL/SQL execution elapsed time 52290858
As you can see, the timetamp is increasing by 2/100s of a second or so per loop. Which is not as quick as I hoped but it is a test box. Note that the counters for DB Time, CPU time, SQL execute elapsed time and PL/SQL execution elapsed time are constant.
A few iterations later we see the v$sess_time_model counters increment:
7 53.509351 DB time 475860419 7 53.509351 DB CPU 402642660 7 53.509351 sql execute elapsed time 209780319 7 53.509351 PL/SQL execution elapsed time 52291610 --all change! 8 53.531378 DB time 475871716 8 53.531378 DB CPU 402653957 8 53.531378 sql execute elapsed time 209786745 8 53.531378 PL/SQL execution elapsed time 52292793 -- and stable 9 53.555889 DB time 475871716 9 53.555889 DB CPU 402653957 9 53.555889 sql execute elapsed time 209786745 9 53.555889 PL/SQL execution elapsed time 52292793
The counters all increment between iteration 7 and 8 and then stay the same. I can’t tell how long the counters had been the same, I need to wait and see when they change again. How long until they increment again? Well, not very long, in fact just around 0.12 seconds:
14 53.650154 DB time 475871716 14 53.650154 DB CPU 402653957 14 53.650154 sql execute elapsed time 209786745 14 53.650154 PL/SQL execution elapsed time 52293064 -- change 15 53.670358 DB time 475881268 15 53.670358 DB CPU 402663509 15 53.670358 sql execute elapsed time 209792803 15 53.670358 PL/SQL execution elapsed time 52294180 -- still changing 16 53.689011 DB time 475887530 16 53.689011 DB CPU 402669771 16 53.689011 sql execute elapsed time 209794387 16 53.689011 PL/SQL execution elapsed time 52294180 -- and still changing 17 53.710875 DB time 475889549 17 53.710875 DB CPU 402671790 17 53.710875 sql execute elapsed time 209796393 17 53.710875 PL/SQL execution elapsed time 52295342 -- ...still changing... 18 53.728168 DB time 475893032 18 53.728168 DB CPU 402675273 18 53.728168 sql execute elapsed time 209797665 18 53.728168 PL/SQL execution elapsed time 52295342 -- and stable 19 53.744725 DB time 475893032 19 53.744725 DB CPU 402675273 19 53.744725 sql execute elapsed time 209797665 19 53.744725 PL/SQL execution elapsed time 52295342
This time, the increment occurs over several iterations of the loop before becoming stable again. All four values I am pulling out increment over these iterations.
The next increment comes four iterations or 0.1 seconds later and happens swiftly, between two iterations:
22 53.802486 DB time 475893032 22 53.802486 DB CPU 402675273 22 53.802486 sql execute elapsed time 209797665 22 53.802486 PL/SQL execution elapsed time 52295342 -- change 23 53.822231 DB time 475897963 23 53.822231 DB CPU 402680204 23 53.822231 sql execute elapsed time 209800369 23 53.822231 PL/SQL execution elapsed time 52296904 -- stable 24 53.840085 DB time 475905724 24 53.840085 DB CPU 402687965 24 53.840085 sql execute elapsed time 209803330 24 53.840085 PL/SQL execution elapsed time 52296904
So it seem that v$sess_time_model is incremented in steps, not constantly, and does so every 0.10 to 0.13 seconds or so. My work here is done.
Or is it?
No, it is not, as there is now a “massive” gap where the counters do not increment for almost 3/4 of a second, until iteration 127:
126 55.530398 DB time 475905724 126 55.530398 DB CPU 402687965 126 55.530398 sql execute elapsed time 209803775 126 55.530398 PL/SQL execution elapsed time 52297583 -- change 127 55.545085 DB time 475914013 127 55.545085 DB CPU 402696254 127 55.545085 sql execute elapsed time 209809518 127 55.545085 PL/SQL execution elapsed time 52298886 -- still changing 128 55.560141 DB time 475921342 128 55.560141 DB CPU 402703583 128 55.560141 sql execute elapsed time 209812345 128 55.560141 PL/SQL execution elapsed time 52299359 -- still changing 129 55.574806 DB time 475922705 129 55.574806 DB CPU 402704946 129 55.574806 sql execute elapsed time 209812345 129 55.574806 PL/SQL execution elapsed time 52299359 -- stable 130 55.589541 DB time 475922705 130 55.589541 DB CPU 402704946 130 55.589541 sql execute elapsed time 209812345 130 55.589541 PL/SQL execution elapsed time 52299359
Again, the incrementing ran over a small number of iterations of my loop.
I think I have shown that all the values increment together so I will reduce my output to just the one counter and see when it increments and over how many iterations and see if a pattern appears:
25 53.860550 DB time 475905724 -- 53.84 to 55.54 0 1.7 seconds of stability 126 55.530398 DB time 475905724 127 55.545085 DB time 475914013 128 55.560141 DB time 475921342 129 55.574806 DB time 475922705 136 55.682402 DB time 475922705 137 55.697191 DB time 475956738 138 55.712266 DB time 475969859 139 55.727820 DB time 475974350 140 55.743315 DB time 475982356 141 55.758749 DB time 475994069 142 55.773602 DB time 476004596 143 55.788472 DB time 476004596 144 55.803295 DB time 476007541 145 55.818136 DB time 476011172 146 55.832886 DB time 476020336 147 55.847772 DB time 476025376 148 55.865303 DB time 476036347 -- incrementd with a couple of brief pauses over 0.34 seconds 149 55.881480 DB time 476041481 150 55.896735 DB time 476041481 ... 200 56.664783 DB time 476041481 -- 55.88 to 56.67 0.8 seconds of stability 201 56.679455 DB time 476049162 -- increments over two iterations, 0.03 seconds 202 56.694092 DB time 476052385 203 56.708733 DB time 476052385 ... 261 57.566902 DB time 476052385 -- 56.69 to 57.59 0.9 seconds of stability 262 57.581582 DB time 476052842 263 57.596218 DB time 476058537 ... 270 57.700212 DB time 476058537 271 57.715371 DB time 476060552 272 57.730797 DB time 476063551 273 57.745700 DB time 476074383 274 57.760351 DB time 476079741 ... 279 57.835162 DB time 476079741 280 57.849966 DB time 476080090 281 57.864782 DB time 476090799 282 57.879446 DB time 476100404 283 57.894553 DB time 476103222 -- stable again after 0.3 seconds and a couple of mini-pauses 284 57.910592 DB time 476103222 ... 335 58.677438 DB time 476103222 -- 57.91 to 58.69 0.8 seconds of stability 336 58.694704 DB time 476113168 337 58.709995 DB time 476113909 338 58.724782 DB time 476119452 339 58.740756 DB time 476119795 340 58.758659 DB time 476129752 341 58.776040 DB time 476132036 ... 345 58.854895 DB time 476132036 346 58.869516 DB time 476138982 347 58.884100 DB time 476145880 348 58.898772 DB time 476160301 349 58.913401 DB time 476178139 350 58.935391 DB time 476183281 -- stable again after 0.27 seconds 351 58.955195 DB time 476183281 ... 395 59.608368 DB time 476183281 -- 57.93 to 59.60 0.68 seconds of stability 396 59.623062 DB time 476187188 ... 402 59.713566 DB time 476187188 403 59.728220 DB time 476194591 404 59.742900 DB time 476204006 405 59.757544 DB time 476210666 406 59.774934 DB time 476216338 407 59.796595 DB time 476228874 ... 413 59.890172 DB time 476228874 414 59.908436 DB time 476238680 415 59.923166 DB time 476251316 416 59.937805 DB time 476259466 417 59.952540 DB time 476261228 418 59.967215 DB time 476277094 419 59.981914 DB time 476282108 -- stable again after 0.29 seconds 420 00.000358 DB time 476298216 ... 529 01.684500 DB time 476298216 -- 00.00 to 01.69 1.69 seconds of stability 530 01.699165 DB time 476301888 531 01.714307 DB time 476312510
I would say that we can draw a few conclusions from the above
- It is dangerous to look at a little bit of data and draw a firm conclusion, as I nearly did
- The data in v$sess_time_model is only maintained in near-time not real-time
- The counters in v$sess_time_model increment together
- The counters seem to increment in a slightly messy way over part of a second and then are stable for 3/4 of a second to a second or two
I wonder how many of you went “Oh dear” when I said I could derive what is true for v$sys_time_model from v$sess_time_model? Could I? well, here is the modified script for v$sys_time_model:
--test_vstm_upd2
-- how often is v$sysstat updated
set trims on
set term off
set serveroutput on size unli
spool test_vstm_upd2
begin
for a in 1..1000 loop
for vrec in
(select rpad(rpad(to_char(a),4)||' '||to_char(systimestamp,'ss.ff')||' '|| stat_name||' ',45)||value rec
from v$sys_time_model
--where sid=1989
where stat_id in (3649082374)
)
loop
dbms_output.put_line(vrec.rec);
end loop;
-- dbms_output.put_line(chr(9));
end loop;
end;
/
set term on
spool off
And a sample of my output:
1 43.187666 DB time 14429733395433 2 43.188523 DB time 14429733395755 3 43.188642 DB time 14429733395905 4 43.188733 DB time 14429733395905 5 43.188822 DB time 14429733395905 6 43.188909 DB time 14429733395905 -- 7 43.188995 DB time 14429733396491 8 43.189080 DB time 14429733396491 9 43.189164 DB time 14429733396491 10 43.189258 DB time 14429733396491 11 43.189345 DB time 14429733396491 12 43.189430 DB time 14429733396491 13 43.189515 DB time 14429733396491 14 43.189600 DB time 14429733396491 15 43.189687 DB time 14429733396491 16 43.189774 DB time 14429733396491 17 43.189858 DB time 14429733396491 18 43.189942 DB time 14429733396491 19 43.190026 DB time 14429733396491 20 43.190111 DB time 14429733396491 -- 21 43.190200 DB time 14429733397436 22 43.190287 DB time 14429733397436 23 43.190371 DB time 14429733397436 24 43.190454 DB time 14429733397436 25 43.190540 DB time 14429733397436 26 43.190624 DB time 14429733397436 27 43.190708 DB time 14429733397436 -- 28 43.190793 DB time 14429733397764 29 43.190877 DB time 14429733397764 30 43.190961 DB time 14429733397764 31 43.191045 DB time 14429733397764 32 43.191132 DB time 14429733397764 33 43.191221 DB time 14429733397764 34 43.191309 DB time 14429733397764 35 43.191392 DB time 14429733397764 -- 36 43.191475 DB time 14429733402416 37 43.191558 DB time 14429733402416 -- 38 43.191641 DB time 14429733403070 39 43.191725 DB time 14429733403070 40 43.191809 DB time 14429733403070 41 43.191893 DB time 14429733403070 42 43.191976 DB time 14429733403070 43 43.192060 DB time 14429733403070 44 43.192144 DB time 14429733403070 45 43.192230 DB time 14429733403070 46 43.192315 DB time 14429733403070 47 43.192400 DB time 14429733403070 48 43.192484 DB time 14429733403070 49 43.192569 DB time 14429733403070 50 43.192654 DB time 14429733403070 -- 51 43.192737 DB time 14429733407045 52 43.192821 DB time 14429733407045 53 43.192904 DB time 14429733407045 54 43.192985 DB time 14429733407045 55 43.193069 DB time 14429733407045 56 43.193152 DB time 14429733407045 57 43.193237 DB time 14429733407045 58 43.193321 DB time 14429733407045 59 43.193404 DB time 14429733407045 60 43.193488 DB time 14429733407045 61 43.193574 DB time 14429733407045 -- 62 43.193660 DB time 14429733408897 63 43.193743 DB time 14429733408897 64 43.193828 DB time 14429733408897 65 43.193912 DB time 14429733408897 66 43.193994 DB time 14429733408897 67 43.194076 DB time 14429733408897 -- 68 43.194160 DB time 14429733409208 69 43.194283 DB time 14429733409208 70 43.194378 DB time 14429733409208 -- 71 43.194465 DB time 14429733409267 72 43.194551 DB time 14429733409267 73 43.194635 DB time 14429733409267 74 43.194719 DB time 14429733409267 75 43.194801 DB time 14429733409267 76 43.194884 DB time 14429733409267 -- 77 43.194967 DB time 14429733409863 78 43.195052 DB time 14429733409863 -- 79 43.195136 DB time 14429733410499 80 43.195245 DB time 14429733410499 81 43.195329 DB time 14429733410499 82 43.195412 DB time 14429733410499 83 43.195495 DB time 14429733410499 84 43.195577 DB time 14429733410499 85 43.195660 DB time 14429733410499 86 43.195743 DB time 14429733410499 87 43.195825 DB time 14429733410499 88 43.195909 DB time 14429733410499 89 43.195991 DB time 14429733410499 90 43.196074 DB time 14429733410499 91 43.196156 DB time 14429733410499 92 43.196244 DB time 14429733410499 93 43.196326 DB time 14429733410499 94 43.196409 DB time 14429733410499 -- 95 43.196493 DB time 14429733411732 96 43.196577 DB time 14429733411732 97 43.196661 DB time 14429733411732 98 43.196745 DB time 14429733411732 99 43.196826 DB time 14429733411732 -- 100 43.196910 DB time 14429733412107 101 43.196992 DB time 14429733412410 102 43.197076 DB time 14429733412410 103 43.197158 DB time 14429733412410 104 43.197245 DB time 14429733412410 105 43.197327 DB time 14429733412410 106 43.197410 DB time 14429733412410 107 43.197493 DB time 14429733412410 108 43.197575 DB time 14429733412410 109 43.197658 DB time 14429733412410 -- 110 43.197741 DB time 14429733412981 111 43.197824 DB time 14429733412981 112 43.197907 DB time 14429733412981 113 43.197990 DB time 14429733412981 114 43.198072 DB time 14429733413001 115 43.198156 DB time 14429733413001 116 43.198247 DB time 14429733413001 117 43.198330 DB time 14429733413001 -- 118 43.198414 DB time 14429733413300 119 43.198499 DB time 14429733413300 120 43.198581 DB time 14429733413300 121 43.198665 DB time 14429733413300 122 43.198748 DB time 14429733413300 123 43.198830 DB time 14429733413300 124 43.198913 DB time 14429733413300 -- 125 43.198997 DB time 14429733414262 126 43.199081 DB time 14429733414262 127 43.199165 DB time 14429733414262 128 43.199252 DB time 14429733414262 129 43.199336 DB time 14429733414262 130 43.199419 DB time 14429733414262 131 43.199503 DB time 14429733414262 -- 132 43.199586 DB time 14429733414569 133 43.199669 DB time 14429733414569 134 43.199752 DB time 14429733414569 135 43.199834 DB time 14429733414569 136 43.199918 DB time 14429733414569 137 43.200000 DB time 14429733414569 138 43.200083 DB time 14429733414569 139 43.200166 DB time 14429733414569 140 43.200252 DB time 14429733414569 -- 141 43.200334 DB time 14429733415145 142 43.200418 DB time 14429733415145 -- 143 43.200504 DB time 14429733415335 144 43.200588 DB time 14429733415335 145 43.200672 DB time 14429733415335 146 43.200756 DB time 14429733415335 147 43.200838 DB time 14429733415335 148 43.200921 DB time 14429733415335 149 43.201003 DB time 14429733415335 150 43.201086 DB time 14429733415335 151 43.201169 DB time 14429733415335 152 43.201259 DB time 14429733415335
I would say that we can draw a few conclusions from this latest test above!
- It is dangerous to look at one thing and assume something closely related will be the same!
- The data in v$sys_time_model is also being updated in bursts
- The data in v$sys_time_model is actually updated very, very frequently, at around 1/1000 of a second intervals
- It might be that v$sess_time_model is being updated for sessions in some sort of round-robin fashion and v$sys_time_model each time the v$sess version is updated
- You can spend a lot of time looking at really quite obscure and possibly pointless stuff
- The reason I am losing weight is I keep skipping lunch.
Martin Widlake's Yet Another Oracle Blog 