jump to navigation

How often is v$sys_time_model updated? July 14, 2010

Posted by mwidlake in internals, performance.
Tags: ,
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.
Follow

Get every new post delivered to your Inbox.

Join 170 other followers