pug challenge emea
TRANSCRIPT
1
Click to edit Master title style
PUG Challenge EMEA
Promon for Dummies & Savants
Presented by: Dan [email protected]
And how it may help in troubleshooting certain DB problems
2
Dan Foreman
• Progress User since 1984
• Recent Employment History is erratic
– Polar Cryogenics 1983 - 1995
– BravePoint 1995 – 2014
– Progress 11/2014 - 7/2016
– Strategic Information Group 7/2016 - 12/2016
– White Star Software 2017 till death?
3
Dan Foreman
• Author of several Progress related Publications
– Progress Performance Tuning Guide
• This year is the 25th Anniversary of the Tuning Guide!
• 1992 : 140 pages in 18 point font
• 2017: 475 pages in 13 point font
– Progress Database Administration Guide
– Progress System Table Guide
– Available in book (paper) or electronic media
• Basketball Fanatic…which sometimes leads to
unexpected trips to the ER
4
Dan Foreman
5
Promon basics
• promon first appeared in Progress V5
• Totally overhauled in V6.3 when the new Shared Memory
architecture was introduced
• Basic concept: Take a snapshot of a particular section of
DB Shared Memory
• Therefore there is no promon option for single user mode
• Limitations:
– Single database
– Fixed Character Interface
– No Warnings or Alerts
6
Promon versus Virtual System Tables
• Virtual System Tables were introduced in V8
• Initially VSTs just replicated the promon menu structure
• Eventually there was functionality added that didn’t exist
in promon
• Examples:
– _tablestat – Table Level I/O
– _indexstat – Index Level I/O
• Tools that use the VSTs
– ProTop
– ProMonitor
– OpenEdge Management
7
Important Metrics – Top Level – 3. Block Access
• DB Requests – the number of times a shared memory
client requested a DB Block
• DB Reads – the number of times the block requested was
not in the DB Buffer Cache (-B/-B2) and had to be
retrieved from storage
• Data displayed for the entire DB and individual Client
processes (if they are connected at the time of the
snapshot)
Type Usr:Ten Name Domain DB Requests DB Reads BI Reads AI Reads
\Writes \Writes \Writes
Acc 99999 TOTAL... 0 554 32 9 0
3 2 0
Acc 0 Dan2 0 440 30 9 0
3 2 0
8
Important Metrics – Top Level – 4. Lock Table
• I recommend using the _Lock VST for monitoring &
debugging record locking issues
• The promon view of the Lock Table doesn’t have filters so
it can be difficult to locate locking conflicts
• The performance issues of accessing _Lock were fixed in
V11.4
9
Important Metrics – Top Level – 5. Activity
Activity - Sampled at 04/20/17 10:41 for 0:04:09.
Event Total Per Sec Event Total Per Sec
Commits 5124393 20579.9 Undos 0 0.0
Record Updates 0 0.0 Record Reads 42494536 170660.8
Record Creates 5124394 20579.9 Record Deletes 0 0.0
DB Writes 179767 722.0 DB Reads 1190 4.8
BI Writes 348934 1401.3 BI Reads 15627 62.8
AI Writes 0 0.0
Record Locks 20497601 82319.7 Record Waits 0 0.0
Checkpoints 5207 20.9 Buffs Flushed 149638 601.0
Rec Lock Waits 0 % BI Buf Waits 1 % AI Buf Waits 0 %
Writes by APW 13 % Writes by BIW 26 % Writes by AIW 0 %
Buffer Hits 100 % Primary Hits 100 % Alternate Hits 0 %
DB Size 633 MB BI Size 2168 K AI Size 0 K
FR chain 59 blocks RM chain 3 blocks
Shared Memory 17669K Segments 1
0 Servers, 2 Users (2 Local, 0 Remote, 0 Batch),1 Apws
10
Important Metrics – Top Level – 5. Activity
• DB Uptime – because many of the metrics are based
upon how long the DB has been running
• Record Reads
• Record Waits
• Checkpoints – CPs will be discussed in more detail later
in this presentation
• Buffers Flushed
– Zero is a perfect ‘score’ but not always possible
• Buffer Hits % - MISLEADING METRIC – The Buffer Hit
Ratio is a much better measurement of DB Cache
effectiveness
11
Important Metrics – Top Menu – 6. Shared Resources
• Locking table entries in use
• Locking table high water mark
12
Important Settings – Top Level – 7. Database Status
• Database block size
• Before Image Block Size
• After Image Block Size
• Before Image Cluster Size
Database Status:
Database version number: 4269
Database state: Open (1)
Database damaged flags: None (0)
Integrity flags: None (1536)
Database block size (bytes): 4096
Total number of database blocks: 204466
Database blocks high water mark: 204374
Free blocks below highwater mark: 59
Record blocks with free space: 3
Before image block size (bytes): 8192
Before image cluster size (kb): 512
After image block size (bytes): 8192
13
R&D Section
• History
– Originally undocumented
– First public documentation appeared in my Progress
Performance Tuning Guide but was not “approved” by
Progress Software
– Eventually (sort of) documented by Progress
• Full of stuff that is useless to a DBA
• But also full of equally important stuff
14
R&D Section
04/20/17 OpenEdge Release 11 Monitor (R&D)
10:49:34 Main (Top) Menu
1. Status Displays ...
2. Activity Displays ...
3. Other Displays ...
4. Administrative Functions ...
5. Adjust Monitor Options
15
R&D Section – 1. Status
04/20/17 OpenEdge Release 11 Monitor (R&D)
10:50:41 Status Displays Menu
1. Database
2. Backup
3. Servers
4. Processes/Clients ...
5. Files
6. Lock Table
7. Buffer Cache
8. Logging Summary
9. BI Log
10. AI Log
11. Two-Phase Commit
12. Startup Parameters
13. Shared Resources
14. Shared Memory Segments
15. AI Extents
16. Database Service Manager
17. Servers By Broker
18. Client Database-Request Statement Cache ...
19. Schema Locks & Wait Queue
20. Broker Startup Parameters
16
Important Metrics – R&D – 1. Status
• 4. Processes/Clients > 2. Blocked Clients
• Shows record lock conflicts and some (but not all!!)
shared memory contention
• More info on this later in the session
17
Important Metrics – R&D – 1. Status
• 7. Buffer Cache
• Empty Buffers indicate potentially wasted memory
Total buffers: 3002
Hash table size: 887
Used buffers: 40
Empty buffers: 2962
18
Important Metrics – R&D – 1. Status
• 16. Database Service Manager
• Very important for OpenEdge Replication users
• Related to the –pica Cache
Communication Area Size : 65.00 KB
Total Message Entries : 595
Free Message Entries : 595
Used Message Entries : 0
Used HighWater Mark : 0
Area Filled Count : 0
Service Latch Holder : -1
Access Count : 0
Access Collisions : 0
19
Important Metrics – R&D – 1. Status
• 9. BI Log
• The only place that you can actually experience the duration of a Checkpoint; the same duration that users feel
Before-image cluster age time: 0 seconds
Before-image block size: 8192 bytes
Before-image cluster size: 512 kb (524288 bytes)
Number of before-image extents: 1
Before-image log size (kb): 2168
Bytes free in current cluster: 52215 (20 %)
Last checkpoint was at: 04/19/17 10:58
Number of BI buffers: 20
Full buffers: 0
20
Important Metrics – R&D – 2. Activity
04/20/17 OpenEdge Release 11 Monitor (R&D)
11:16:33 Activity Displays Menu
1. Summary
2. Servers
3. Buffer Cache
4. Page Writers
5. BI Log
6. AI Log
7. Lock Table
8. I/O Operations by Type
9. I/O Operations by File
10. Space Allocation
11. Index
12. Record
13. Other
21
Important Metrics – R&D – 2. Activity
• 5. BI Log
Total Per Min Per Sec Per Tx
Total BI writes 2 0 0.00 0.00
BIW BI writes 0 0 0.00 0.00
Records written 0 0 0.00 0.00
Bytes written 0 0 0.00 0.00
Total BI Reads 9 0 0.01 0.00
Records read 0 0 0.00 0.00
Bytes read 0 0 0.00 0.00
Clusters closed 0 0 0.00 0.00
Busy buffer waits 0 0 0.00 0.00
Empty buffer waits 0 0 0.00 0.00
Log force waits 0 0 0.00 0.00
Log force writes 0 0 0.00 0.00
Partial writes 2 0 0.00 0.00
Input buffer hits 0 0 0.00 0.00
Output buffer hits 0 0 0.00 0.00
Mod buffer hits 0 0 0.00 0.00
BO buffer hits 0 0 0.00 0.00
22
Important Metrics – R&D – 2. Activity
• 13. Other
• See Rich Banville’s session on Shared Memory
Contention from 2008 Exchange
Total Per Min Per Sec Per Tx
Commit 0 0 0.00 0.00
Undo 0 0 0.00 0.00
Wait on semaphore 0 0 0.00 0.00
Non-blocking waits 0 0 0.00 0.00
Semaphore latch waits 0 0 0.00 0.00
Flush master block 3 0 0.00 0.00
23
Brief History of the debghb option in promon
• Added to promon V6.3 by Gus
• Purpose: The shared memory architecture introduced in
V6.3 was new and very different from earlier versions
and a way to monitor shared memory activity at a
detailed level was needed
• The debghb option was not a formally endorsed
enhancement but written by Gus in his spare time
• deb = DEBug
• ghb = Gus’s initials….the middle initial is a Top Secret
fanatically guarded by the Finnish government
24
Warning
• The debghb option is not formally documented by Progress
• DO NOT call or email Gus or PTS for help in using this
option
• Many of the screens and/or metrics have no value to a
DBA
• The view of the data is not transactionally consistent
sometimes even on the same screen; example to follow
• Some of the data is not accurate (data overflow, rounding
errors, etc)
• Some of the screens are broken (don’t display any data)
• The debghb option can be altered, removed, or hidden by
Progress any time they want to
25
Warning #2
• DB activities in shared memory can be slowed down if
certain options are enabled
05/08/13 OpenEdge Release 10 Monitor (R&D)
19:10:44 Adjust Latch Options
1. Spins before timeout: 24000
2. Enable latch activity data collection
3. Enable latch timing data collection
4. Initial latch sleep time: 10 milliseconds
5. Maximum latch sleep time: 5000 milliseconds
6. Record Free Chain Search Depth Factor: 5
26
How do I access debghb?
• Start promon
• Enter: R&D (also works in lower case starting in V10)
• Enter: debghb
• You have now entered the debghb “zone”
• Two main differences in the world of debghb
– Extensions to some existing R&D screens
– Enables access to “This menu is not here Menu”
• Enter: “6” even though there is no visible option 6
• See next slide
27
This menu is not here Menu
06/06/13 OpenEdge Release 10 Monitor (R&D)
15:23:01 This menu is not here Menu
1. Cache Entries
2. Hash Chain
3. Page Writer Queue
4. Lru Chains
5. Locked Buffers
6. Buffer Locks
7. Buffer Use Counts
8. Resource Queues
9. TXE Lock Activity
10. Adjust TXE Options
11. Latch Counts
12. Latch Times
13. I/O Wait Time by Type
14. I/O by File
15. Buffer Lock Queue
16. Semaphores
17. Shutdown
28
Operating Hints
• Allow at least 40-45 lines of screen data
• Allow at least 120-140 columns of screen width
• Zero out the stats (“z”) to get a clean starting place
– This ‘zeroing’ does not wipe out the actual shared memory
counters but only affects the current promon session
• Update the stats periodically (“u”) to get snapshots
• All the above can be scripted
29
Operating Hints - User# -1
• Usecnt = # of concurrent processes accessing the block
• When initially examining the BLQ there were 5 Clients
accessing the same DBKEY
• But before all 5 could be displayed:
– One Client left, i.e. released the Lock, before it was displayed
– Another one of the 5 is partially displayed; i.e. the -1 User#
– That’s the “nice” reason; the probable reason is it’s a bug
02/06/13 Status: Buffer Lock Queue
00:37:21
User DBKEY Area T Status Type Usect
-1 70658368 34 I LOCKED SHARE 5
746 70658368 34 I LOCKED SHARE 3
762 70658368 34 I LOCKED SHARE 3
826 70658368 34 I LOCKED SHARE 3
30
Useful Screens - Checkpoints
• Extensions to the ‘normal’ Checkpoint screen added in V10.2B SP5
• Columns of interest
– Duration: the amount of time required to complete a Checkpoint; the entire Database is transactionally frozen during this time
• _CheckPoint._CheckPoint-Duration (V10.2B SP5)
– Sync Time: a subset of the ‘Duration’ column; the amount of time required to execute fdatasync() system call
• _CheckPoint._CheckPoint.Synctime (V10.2B SP5)
• See http://www.makelinux.net/alp/060 for an excellent description of fdatasync (don’t confuse it with fsync).
• Sample data on the next slide
31
Useful Screens - Checkpoints
• The ‘Duration’ of the Checkpoints (i.e. the total freeze
time) is very high for most of the CPs displayed
• A ‘Duration’ of less than 1 second is a good goal
• The 10 sec ‘Duration’ is approximately 1/3 of the CP
‘Freq’. In other words, a CP is occurring approximately
every 30-35 seconds and for up to 10 seconds of that
period, NO Client transaction activity can take place.
Ckpt ------ Database Writes ----
No. Time Len Freq Dirty CPT Q Scan APW Q Flushes Duration Sync Time
2499 00:56:04 246 265 14097 14586 3003 62 0 2.12 0.42
2498 00:52:16 212 228 33792 35191 2915 199 0 6.49 4.85
2497 00:51:40 33 36 34536 37114 229 85 0 7.15 5.96
2496 00:51:09 30 31 34385 36950 164 151 0 7.22 5.89
2495 00:50:34 34 35 37992 40285 408 341 0 8.33 7.15
2494 00:49:59 34 35 40933 43429 132 363 0 10.20 9.05
2493 00:49:29 29 30 41377 43427 690 281 0 5.39 3.84
32
Useful Screens - Checkpoints
10/05/16 Checkpoints
12:57:08
Ckpt ------------ Database Writes ------------- --------- Performance Timings --------
No. Time Len Freq Dirty CPT Q Scan APW Q DB Writes Bi Writes Duration Sync Time DB Write Bi Write NumChkpt
6 12:57:06 2 0 2088 1063 1 250 0 5 0.00 0.00 0.00 0.00 1315
5 12:57:00 6 6 2099 2001 7 97 1 31 0.01 0.00 0.00 0.01 2098
4 12:56:56 4 4 1907 1845 6 62 0 32 0.03 0.02 0.00 0.01 1907
3 12:56:53 3 3 1267 1267 3 0 0 1 0.01 0.01 0.00 0.00 1267
2 12:56:49 4 4 831 831 0 0 0 87 0.02 0.01 0.00 0.02 831
1 12:55:43 66 66 1746 1746 261 0 0 73 0.01 0.00 0.00 0.01 1746
0 12:54:16 43 87 0 0 0 0 0 0 0.00 0.00 0.00 0.00 0
• In V11.6 the Checkpoint Duration is broken down even
further. Thank you Rich Banville!! (except that I have to
use a tiny font to fit everything on one line)
– Sync Time
– DB Write
– BI Write
33
Useful Screens – Resource Queues
• NHM (Not Here Menu) - Option #8
• Do not confuse Resources with Latches; Rich Banville
gave a good talk on this topic at Exchange 2008
• In general the busiest locks will be:
– DB Buf S Lock (S = Share)
– DB Buf X Lock (X= Exclusive)
– Record Lock
• Waits that can be problematic:
– DB Buf I Lock (I = Intent but these are for Index blocks)
– Sample on the next slide
34
Useful Screens – Resource Queues
01/31/13 Activity: Resource Queues
00:31:57 01/31/13 00:26 to 01/31/13 00:31 (5 min)
Queue - Requests - ------- Waits -------
Total /Sec Total /Sec Pct
Record Lock 1007903 3360 8 0 0.00
Trans Commit 1631 5 0 0 0.00
DB Buf I Lock 1006724 3356 139476 465 0.14
Record Get 724869 2416 0 0 0.00
DB Buf Read 305596 1019 0 0 0.00
DB Buf Write 62727 209 0 0 0.00
DB Buf S Lock 33370848 111236 159591 532 0.00
DB Buf X Lock 1092894 3643 157022 523 0.14
DB Buf S Lock LRU2 20934886 69783 0 0 0.00
DB Buf X Lock LRU2 11088 37 0 0 0.00
DB Buf Write LRU2 3367 11 0 0 0.00
BI Buf Read 4788 16 0 0 0.00
BI Buf Write 16075 54 1096 4 0.07
TXE Share Lock 1148821 3829 0 0 0.00
TXE Update Lock 10347 34 282 1 0.03
TXE Commit Lock 63540 212 1927 6 0.03
35
Useful Screens – Latch Counts
• NHM (Not Here Menu) - Option #11
• The R&D Blocked Clients screen doesn’t show Latch
contention so debghb is the only place in promon where
detailed Latch activity is visible
• Definition of Naps: When –spin is ‘used up’ by a Progress
Client, the process Naps (i.e. does no useful work) for a
while and tries again
• General Principle: Napping is bad (unless it’s my wife)
• Samples on the next few slides
36
Latch Counts – OM Latch
• OM (Object Cache) Latch activity can be totally eliminated
by setting the -omsize parameter equal to or greater than
the number of _StorageObject records
04/24/13 Activity: Latch Counts
00:59:28 04/24/13 00:54 to 04/24/13 00:59 (5 min 1 sec)
----- Locks ----- --- Busy --- Naps -------- Spins -------- -- Nap Max -
Owner Total /Sec /Sec Pct /Sec /Sec /Lock /Busy Total HWM
MTX -- 1563935 5195 86 1.6 45 6461297 1243 74724 259 300
USR -- 1178290 3914 3 0.0 0 0 0 0 0 0
OM -- 21523860 71507 7322 10.2 139 9144588 127 1248 3 80
37
Latch Counts – USR Latch
• The contention on the USR (DB Connection Table) Latch
is because Statement Caching is enabled04/25/13 Activity: Latch Counts
00:33:17 04/25/13 00:28 to 04/25/13 00:33 (5 min 0 sec)
----- Locks ----- ---- Busy --- Naps --------- Spins ---------- --- Nap Max
Owner Total /Sec /Sec Pct /Sec /Sec /Lock /Busy Total HWM
MTX -- 2402181 8007 17 0.2 45 2059022 257 120481 133 300
USR -- 1517252 5057 8 0.1 0 0 0 0 0 0
OM 4343 27667792 92225 1962 2.1 32 5781905 62 2946 0 80
BIB -- 2170630 7235 0 0.0 1 49241 6 165982 11 300
SCH -- 447 1 0 0.0 0 0 0 0 0 0
LKP -- 90680 302 0 0.0 0 6 0 923 0 10
GST -- 195 0 0 0.0 0 200 307 0 1 10
TXT -- 703633 2345 0 0.0 0 811 0 10149 0 10
SEQ -- 505781 1685 0 0.0 0 18283 10 66889 4 10
AIB -- 1947241 6490 0 0.0 0 4957 0 43745 1 20
TXQ -- 3304146 11013 5 0.0 1 116828 10 20788 0 20
EC -- 0 0 0 0.0 0 0 0 0 0 0
LKF -- 1834458 6114 1 0.0 0 16091 2 15673 7 10
BFP -- 0 0 0 0.0 0 0 0 0 0 0
BHT -- 63583335 211944 40 0.0 9 1511922 7 37429 13 300
PWQ -- 491 1 0 0.2 0 23 14 7184 0 0
CPQ -- 535397 1784 0 0.0 0 23253 13 47135 0 160
LRU -- 812009 2706 0 0.0 2 129408 47 160424 0 80
LRU -- 0 0 0 0.0 0 0 0 0 0 0
BUF -- 39136969 130456 13 0.0 1 191806 1 13868 3 40
38
Latch Counts – LRU Chain
• The total number of Locks for LRU is the second highest of all
the Resources shown (BHT – Buffer Hash Table – is #1)
• The # of Naps per Second is the highest of all latches (Zero is
ideal)
01/31/13 Activity: Latch Counts
00:05:38 01/31/13 00:00 to 01/31/13 00:05 (5 min 0 sec)
----- Locks ----- ------ Busy ------ Naps
Owner Total /Sec /Sec Pct /Sec
MTX -- 1654034 5513 0 0.0 15
OM -- 8216844 27389 0 0.0 1
BHT -- 62371320 207904 0 0.0 3
CPQ -- 197126 657 0 0.0 0
LRU 830 40395944 134653 0 0.0 1402
LRU -- 0 0 0 0.0 0
BUF -- 32676880 108922 0 0.0 0
BUF -- 39818994 132729 0 0.0 529
BUF -- 31278094 104260 0 0.0 8
BUF -- 33342130 111140 0 0.0 3
39
Latch Counts – LRU Chain
• The # of locks on the second LRU (Alternate Buffer
Cache, ABC) is zero because all the ABC blocks
completely fit in the amount of –B2 memory allocated
01/31/13 Activity: Latch Counts
00:05:38 01/31/13 00:00 to 01/31/13 00:05 (5 min 0 sec)
----- Locks ----- ------ Busy ------ Naps
Owner Total /Sec /Sec Pct /Sec
BHT -- 62371320 207904 0 0.0 3
CPQ -- 197126 657 0 0.0 0
LRU 830 40395944 134653 0 0.0 1402
LRU -- 0 0 0 0.0 0
BUF -- 32676880 108922 0 0.0 0
BUF -- 39818994 132729 0 0.0 529
40
Latch Counts – LRU Chain
• ‘Owner’ column: if the User# doesn’t change (in value or
frequency) that can be a problem indicator because
Latches should be held for only a fraction of a second
01/31/13 Activity: Latch Counts
00:05:38 01/31/13 00:00 to 01/31/13 00:05 (5 min 0 sec)
----- Locks ----- ------ Busy ------ Naps
Owner Total /Sec /Sec Pct /Sec
BHT -- 62371320 207904 0 0.0 3
CPQ -- 197126 657 0 0.0 0
LRU 830 40395944 134653 0 0.0 1402
LRU -- 0 0 0 0.0 0
BUF -- 32676880 108922 0 0.0 0
BUF -- 39818994 132729 0 0.0 529
41
Using Latch Counts to set -spin
• Short answer – Forget It!
• If it was easy Progress would/should have done it already
• Past attempts have not been successful
• Also the optimal value of –spin is not going to be the
same for each individual Latch
• General guidelines:
– Greater than 1,000
– Less than 50,000
– Current Default: 6,000 * (# of CPU Cores)
• Default is not advised if you have more than 16 Cores
– Dan’s Formula (Patent Pending): (DBA-Birthday-Year * )
– Gus’s “formula”: 5,000
42
Useful Screens – Buffer Lock Queue
• NHM (Not Here Menu) - Option #15
• The ‘normal’ R&D Blocked Clients screen does not show
the Area that the DBKEY belongs to
• The Buffer Lock Queue (BLQ) Screen shows the Area as
well as the Block Type
• Examples on the next two slides
43
R&D Blocked Clients
• The R&D Blocked Clients screen doesn’t show enough
information to identify the Object involved in this
contention storm for DBKEY 65987456
• There were 29 Clients all blocked on the same DBKEY
01/31/13 Status: Blocked Clients
00:26:41
Usr Name Type Wait Wait Info Trans id Login time
730 _AUTO-B SELF/ABL BKSH 65987456 601383708 01/30/13 23:22
735 _AUTO-B SELF/ABL BKSH 65987456 601383773 01/30/13 23:23
743 _AUTO-B SELF/ABL BKSH 65987456 601383921 01/30/13 23:22
747 _AUTO-B SELF/ABL BKSH 65987456 601384104 01/30/13 23:22
749 _AUTO-B SELF/ABL BKSH 65987456 601383895 01/30/13 23:23
755 _AUTO-B SELF/ABL BKSH 65987456 601384175 01/30/13 23:23
769 _AUTO-B SELF/ABL BKSH 65987456 601384161 01/30/13 23:22
44
Buffer Lock Queue
• IF there is a matching DBKEY on the the BLQ screen, we
can get the Area# and the Block Type (I = Index)
• There were 29 processes on the Blocked Clients screen
with this DBKEY and only 4 on the BLQ screen with the
same DBKEY (remember, not transactionally consistent)
01/31/13 Status: Buffer Lock Queue
00:26:41
User DBKEY Area T Status Type Usect
-1 65987456 34 I LOCKED SHARE 4
722 65987456 34 I LOCKED SHARE 4
772 65987456 34 I LOCKED SHARE 4
856 65987456 34 I LOCKED SHARE 4
859 65987456 34 I LOCKED SHARE 4
<lines unrelated to DBKEY 65987456 snipped>