ULC flush par System logs records (sybase 12.5.4)

1 pièce(s) jointe(s)

Bonjour.

sp_sysmon rapporte un grand nombre de "flushs" par system logs records

Je comprend que ce type de "flush" serait causé par des écritures sur les bd définies en "mixed log and data"

Or, nous avons très peu d'écritures dans master,
data et logs sont séparés sur toutes les bd applicatives.

Nous utilisons 4 tempdbs temporaires en ramdisk pour le OLTP (data et logs séparés)

2 autres tempdbs sont en "mixed logs and data" mais sont très peu utilisées.
pendant la période de la prise d'échantillon sp_sysmon.

Qu'est ce qui provoque ces flush???

Code:

1
2
3
4
5
6
7
8
9
10
11
12
13
==================================================================
sampling  sampling  ________Percent_ULC_Flushes_to_Xact_Log_______
started   ended       Full     end  change  Si.log   pages
at        at           ULC  Transa  databa  record   unpin  others
--------  --------  ------  ------  ------  ------  ------  ------
09:00:43  09:15:43    0.2%   34.6%    0.6%   50.2%    8.7%    5.7%
09:16:02  09:17:03    0.2%   42.4%    0.7%   47.1%    4.0%    5.6%
09:17:14  09:18:14    0.4%   39.1%    0.7%   47.7%    5.4%    6.7%
09:18:26  09:19:26    0.4%   38.6%    0.7%   48.1%    6.2%    6.0%
09:19:36  09:20:36    0.5%   36.7%    0.6%   48.1%    8.0%    6.2%
09:20:44  09:21:45    0.3%   39.2%    0.7%   50.0%    3.5%    6.4%
09:21:57  09:22:57    0.4%   39.5%    0.7%   45.9%    5.0%    8.5%
09:23:07  09:24:08    0.4%   38.8%    0.8%   45.7%    7.2%    7.1%

Code:

1
2
3
4
5
6
7
8
9
10
11
12
13
==========================================================================================================================
sampling  sampling  ________per_sec_ULC_Flushes_to_Xact_Log_______  ULC log    Max    ULC    LOG  _per_seconde__       AVG
started   ended       Full     end  change  Si.log   pages          Records    ULC  semap  semap  transactionLOG    writes
at        at           ULC  Transa  databa  record   unpin  others  by tran   size   wait   wait  writes  allocs    log pg
--------  --------  ------  ------  ------  ------  ------  ------  -------  -----  -----  -----  ------  ------  --------
09:00:43  09:15:43     2.1   326.8     5.6   474.5    82.5    54.1     41.6  16384    0.4    0.6   211.4   784.2   0.26962
09:16:02  09:17:03     1.8   354.3     6.0   394.0    33.2    46.6     20.7  16384    0.5    0.2   169.2   375.1   0.45111
09:17:14  09:18:14     3.2   347.9     6.2   424.5    47.8    59.6     26.3  16384    0.5    0.5   170.5   467.8   0.36452
09:18:26  09:19:26     4.3   445.6     8.3   554.8    71.3    69.5     27.3  16384    0.4    0.5   226.5   620.8   0.36488
09:19:36  09:20:36     5.1   404.0     6.6   529.5    88.5    68.1     37.6  16384    1.3    0.5   244.4   737.3   0.33143
09:20:44  09:21:45     3.2   402.4     7.1   513.5    35.6    65.9     24.2  16384    0.4    0.4   179.5   523.8   0.34267
09:21:57  09:22:57     4.0   390.3     7.3   453.6    49.1    84.5     20.4  16384    0.3    0.3   174.9   459.1   0.38087
09:23:07  09:24:08     4.1   393.8     7.7   463.3    73.3    71.6     29.2  16384    0.4    0.2   215.6   569.2   0.37884

Les tables applicatives sont définies avec les clustered index. Je pense que les APL heap inserts sont ceux dans les tempdbs.

Code:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
*** TRANSACTION PROFILE ***
==================================================================================================
sampling  sampling  ___________________________________per_sec____________________________________
started   ended     commit  _________inserts_________  ____updates_____  _________deletes_________
at        at         Xacts  APLheap  APLclus    DOL      APL      DOL    APL-def  APL-dir    DOL
--------  --------  ------  -------  -------  -------  -------  -------  -------  -------  -------
09:00:43  09:15:43     360   8893.0   2897.6     65.1    131.2     33.1    775.0   2904.4     65.0
09:16:02  09:17:03     385   6006.0   1901.8     72.9    183.4     34.0    876.3     77.1     73.7
09:17:14  09:18:14     387   6970.6   3059.9     74.4    179.4     45.0    968.4     87.2     74.0
09:18:26  09:19:26     489   7563.8   4878.2     98.1    230.5     53.5   1272.6     99.7     97.8
09:19:36  09:20:36     450  12567.3   6284.6     89.0    234.3     47.7   1171.2     93.9     88.9
09:20:44  09:21:45     444   6651.1   1659.8     88.7    224.7     47.5   1163.8     88.4     88.2
09:21:57  09:22:57     449   4108.8   2585.6     81.0    283.2     54.3   1153.6     76.7     80.5
09:23:07  09:24:08     439   4852.8   5556.0     83.7    229.0     52.8   1067.4    100.3     83.3

Voici les I/O dans les devices tempdb et master

Code:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
DEVICE DETAILS for tempdb_dx_r_RAM_01  (0)
========================================================
sampling  sampling  _________Per_Second_________  %%%%%%
started   ended          APF    nonAPF            Utili-
at        at           Reads     Reads    Writes  zation
--------  --------  --------  --------  --------  ------
09:00:43  09:15:43       0.0       0.2      47.0    3.7%
09:16:02  09:17:03       0.0       0.4      69.2    9.6%
09:17:14  09:18:14       0.0       0.0      29.7    5.5%
09:18:26  09:19:26       0.0       0.1      47.1    3.8%
09:19:36  09:20:36       0.0       0.2      83.8    7.9%
09:20:44  09:21:45       0.0       0.0      22.2    4.3%
09:21:57  09:22:57       0.0       0.1      44.1    6.5%
09:23:07  09:24:08       0.0       0.0      42.9    3.5%
09:24:19  09:25:19       0.0       0.1      54.7    6.0%
 
DEVICE DETAILS for tempdb2_dx_r_RAM_01  (0)
========================================================
sampling  sampling  _________Per_Second_________  %%%%%%
started   ended          APF    nonAPF            Utili-
at        at           Reads     Reads    Writes  zation
--------  --------  --------  --------  --------  ------
09:00:43  09:15:43      13.3       3.7      71.5    6.9%
09:16:02  09:17:03       0.0       0.0      14.5    2.0%
09:17:14  09:18:14       0.0       0.1      22.8    4.3%
09:18:26  09:19:26       0.0       0.1      32.0    2.6%
09:19:36  09:20:36       0.0       0.0      24.4    2.3%
09:20:44  09:21:45       0.0       0.1      30.3    5.9%
09:21:57  09:22:57       0.0       0.0      31.9    4.7%
09:23:07  09:24:08       0.0       0.0      21.2    1.7%
09:24:19  09:25:19       0.0       0.1      24.6    2.7%
 
 
DEVICE DETAILS for tempdb3_dx_r_RAM_01  (0)
========================================================
sampling  sampling  _________Per_Second_________  %%%%%%
started   ended          APF    nonAPF            Utili-
at        at           Reads     Reads    Writes  zation
--------  --------  --------  --------  --------  ------
09:00:43  09:15:43       0.0       0.1      13.5    1.1%
09:16:02  09:17:03       0.0       0.1      14.1    2.0%
09:17:14  09:18:14       0.0       0.0      16.4    3.1%
09:18:26  09:19:26       0.0       0.1      20.3    1.6%
09:19:36  09:20:36       0.0       0.1      26.0    2.5%
09:20:44  09:21:45       0.0       0.0      13.6    2.6%
09:21:57  09:22:57       0.0       0.1      14.6    2.1%
09:23:07  09:24:08       0.0       0.1      20.2    1.7%
09:24:19  09:25:19       0.0       0.1      26.2    2.9%
 
 
DEVICE DETAILS for tempdb4_dx_r_RAM_01  (0)
========================================================
sampling  sampling  _________Per_Second_________  %%%%%%
started   ended          APF    nonAPF            Utili-
at        at           Reads     Reads    Writes  zation
--------  --------  --------  --------  --------  ------
09:00:43  09:15:43      24.3       5.2     112.0   11.1%
09:16:02  09:17:03       0.0       0.1      37.0    5.1%
09:17:14  09:18:14       0.0       0.1      34.0    6.3%
09:18:26  09:19:26       0.0       0.2      43.2    3.5%
09:19:36  09:20:36       0.0       0.2      36.1    3.4%
09:20:44  09:21:45       0.0       0.1      38.7    7.5%
09:21:57  09:22:57       0.0       0.1      29.1    4.3%
09:23:07  09:24:08       0.0       0.0      39.7    3.3%
09:24:19  09:25:19       0.0       0.1      33.0    3.6%
 
 
DEVICE DETAILS for tempdb_l_r_RAM_01  (0)
========================================================
sampling  sampling  _________Per_Second_________  %%%%%%
started   ended          APF    nonAPF            Utili-
at        at           Reads     Reads    Writes  zation
--------  --------  --------  --------  --------  ------
09:00:43  09:15:43       0.0       0.6      44.7    3.6%
09:16:02  09:17:03       0.0       0.5      36.1    5.0%
09:17:14  09:18:14       0.0       0.7      50.1    9.4%
09:18:26  09:19:26       0.0       0.9      71.8    5.9%
09:19:36  09:20:36       0.0       1.1      84.5    8.1%
09:20:44  09:21:45       0.0       0.4      33.1    6.5%
09:21:57  09:22:57       0.0       0.5      41.2    6.1%
09:23:07  09:24:08       0.0       0.9      72.4    6.0%
 
 
DEVICE DETAILS for tempdb2_l_r_RAM_01  (0)
========================================================
sampling  sampling  _________Per_Second_________  %%%%%%
started   ended          APF    nonAPF            Utili-
at        at           Reads     Reads    Writes  zation
--------  --------  --------  --------  --------  ------
09:00:43  09:15:43       0.9       1.7      47.4    3.9%
09:16:02  09:17:03       0.0       0.2      18.6    2.6%
09:17:14  09:18:14       0.0       0.4      30.0    5.7%
09:18:26  09:19:26       0.0       0.5      38.1    3.1%
09:19:36  09:20:36       0.0       0.5      32.3    3.1%
09:20:44  09:21:45       0.0       0.5      36.9    7.2%
09:21:57  09:22:57       0.0       0.6      39.4    5.9%
09:23:07  09:24:08       0.0       0.4      28.5    2.4%
09:24:19  09:25:19       0.0       0.4      31.7    3.5%
 
 
DEVICE DETAILS for tempdb3_l_r_RAM_01  (0)
========================================================
sampling  sampling  _________Per_Second_________  %%%%%%
started   ended          APF    nonAPF            Utili-
at        at           Reads     Reads    Writes  zation
--------  --------  --------  --------  --------  ------
09:00:43  09:15:43       0.0       0.2      19.5    1.5%
09:16:02  09:17:03       0.0       0.1      12.7    1.8%
09:17:14  09:18:14       0.0       0.3      22.9    4.3%
09:18:26  09:19:26       0.0       0.4      30.8    2.5%
09:19:36  09:20:36       0.0       0.6      42.9    4.1%
09:20:44  09:21:45       0.0       0.2      19.5    3.8%
09:21:57  09:22:57       0.0       0.2      20.8    3.1%
09:23:07  09:24:08       0.0       0.4      32.1    2.7%
09:24:19  09:25:19       0.0       0.5      39.8    4.4%
 
 
DEVICE DETAILS for tempdb4_l_r_RAM_01  (0)
========================================================
sampling  sampling  _________Per_Second_________  %%%%%%
started   ended          APF    nonAPF            Utili-
at        at           Reads     Reads    Writes  zation
--------  --------  --------  --------  --------  ------
09:00:43  09:15:43       1.3       2.7      75.0    6.2%
09:16:02  09:17:03       0.0       0.6      47.6    6.6%
09:17:14  09:18:14       0.0       0.5      41.6    7.8%
09:18:26  09:19:26       0.0       0.6      55.3    4.5%
09:19:36  09:20:36       0.0       0.9      59.0    5.6%
09:20:44  09:21:45       0.0       0.8      61.6   12.1%
09:21:57  09:22:57       0.0       0.5      39.8    5.9%
09:23:07  09:24:08       0.0       0.6      50.4    4.2%
 
 
DEVICE DETAILS for tempdbbatch_dxl_r_tempdb1  (0)
========================================================
sampling  sampling  _________Per_Second_________  %%%%%%
started   ended          APF    nonAPF            Utili-
at        at           Reads     Reads    Writes  zation
--------  --------  --------  --------  --------  ------
09:00:43  09:15:43       0.0       0.0       0.5    0.0%
09:16:02  09:17:03       0.0       0.0       0.1    0.0%
09:17:14  09:18:14       0.0       0.0       0.5    0.1%
09:18:26  09:19:26       0.0       0.0       1.6    0.1%
09:19:36  09:20:36       0.0       0.0       0.1    0.0%
09:20:44  09:21:45       0.0       0.0       0.1    0.0%
09:21:57  09:22:57       0.0       0.0       2.5    0.4%
09:23:07  09:24:08       0.0       0.0       0.1    0.0%
 
 
DEVICE DETAILS for tempDBAIBM_dxl_r_tempdb1#  (0)
========================================================
sampling  sampling  _________Per_Second_________  %%%%%%
started   ended          APF    nonAPF            Utili-
at        at           Reads     Reads    Writes  zation
--------  --------  --------  --------  --------  ------
09:00:43  09:15:43  --------  --------  --------    0.0%
09:16:02  09:17:03  --------  --------  --------    0.0%
09:17:14  09:18:14  --------  --------  --------    0.0%
09:18:26  09:19:26  --------  --------  --------    0.0%
09:19:36  09:20:36  --------  --------  --------    0.0%
09:20:44  09:21:45  --------  --------  --------    0.0%
09:21:57  09:22:57  --------  --------  --------    0.0%
09:23:07  09:24:08  --------  --------  --------    0.0%
 
 
DEVICE DETAILS for master  (0)
========================================================
sampling  sampling  _________Per_Second_________  %%%%%%
started   ended          APF    nonAPF            Utili-
at        at           Reads     Reads    Writes  zation
--------  --------  --------  --------  --------  ------
09:00:43  09:15:43       0.0       0.0       1.3    0.1%
09:16:02  09:17:03       0.0       0.0       1.3    0.2%
09:17:14  09:18:14       0.0       0.0       1.4    0.3%
09:18:26  09:19:26       0.0       0.1       1.5    0.1%
09:19:36  09:20:36       0.0       0.0       1.5    0.1%
09:20:44  09:21:45       0.0       0.0       1.3    0.3%
09:21:57  09:22:57       0.0       0.0       1.4    0.2%
09:23:07  09:24:08       0.0       0.0       1.3    0.1%
09:24:19  09:25:19       0.0       0.1       1.4    0.2%

Des idées?

bonjour

Réaction un peu tardive, peut-être as-tu déjà eu un réponse.

C'est un peu difficile de dire à quoi un compteur sp_sysmon à froid ...

Citation:

In databases with mixed data and log segments, the user log cache is flushed after each record is added.

Autrement dit, ce n'est pas lié au fait que tes bases sont en data/log mélangés. Chaque log record est écrit dès qu'il y a des écritures dans le journal.

Cf. doc Sybase :

Citation:

“by System Log Record” – A system transaction (such as an OAM page allocation) occurred within the user transaction.

Je lierais plutôt ce genre d'activité à des création/suppressions/chargement de tables (temporaires par exemple). Chaque création de table/index, chaque allocation de page (agrandissement ou réduction d'une table), chaque suppression de table/index provoque des allocations/désallocations de pages OAM.

Quelle est la valeur de ton user log cache size ?

a+

Bonjour kagemaru.

Nous avons tellement d'activité dans les tempdb que nous en avons créé quatre en ramdisk (data et logs séparés). Donc, il est probable que créations-suppressions de tables dans les tempdbs expliquent un taux élevé de System log records.

Le ULC est défini a 16384 (notes que le logiosize des tempdbs à la même valeur).

Près de 50% des I/O sont dans ces tempdbs, (99.5% en écriture).
Le nombre de unpins est comparativement bas (autour de 8%).

On dirait que tu as trouvé la cause (OAM) mais je ne m'attendais pas à tant de ULC flushs...

merci.

Citation:

Envoyé par kagemaru

[...]

Je lierais plutôt ce genre d'activité à des création/suppressions/chargement de tables (temporaires par exemple). Chaque création de table/index, chaque allocation de page (agrandissement ou réduction d'une table), chaque suppression de table/index provoque des allocations/désallocations de pages OAM.

Quelle est la valeur de ton user log cache size ?

a+