Hello world!

== Abstract ==

The following article show a simple method to use Glance binary log for resource bootleneck identification. The '''extract''' command is used to export the glance binary data to ASCII text, that can be use for tabular or plot reports.

__TOC__

== Stop Running OVPA agents ==# /sbin/init.d/ovpa stop

Shutting down Perf Agent collection software
Shutting down scopeux, pid(s) 5418
Waiting on 5418 (10 more tries)
The Perf Agent collector, scopeux has been shut down successfully.
The ARM daemons ttd, midaemon and Glance programs glance and xglance will be terminated (if running).

Shutting down the alarm generator perfalarm, pid(s) 5456
The perfalarm process has terminated

Shutting down coda daemon
Shutting down coda, pid(s) 5450
# /opt/perf/bin/perfstat
**********************************************************
*** perfstat for delta on Tue Nov 24 13:23:26 CST 2009
*** HP-UX delta B.11.31 U 9000/800 510254130 unlimited-user license
**********************************************************

list of performance tool processes:
———————————-

Perf Agent status:
WARNING: scopeux is not active (Perf Agent data collector)
WARNING: midaemon is not active (Measurement Interface daemon)
WARNING: ttd is not active (ARM registration daemon)

Perf Agent Server status:

Running ovcd (OV control component) pid 1849
Running ovbbccb (BBC5 communication broker) pid 1860
WARNING: coda is not active (perf component)
WARNING: perfalarm is not active (alarm generator)

******** (end of perfstat output: note above warning) ********

== Backup System Binary Logs ==# tar -cvf – /var/opt/perf/datafiles/log* | /usr/contrib/bin/gzip > /tmp/glancelogs.tgz
a /var/opt/perf/datafiles/logappl 129 blocks
a /var/opt/perf/datafiles/logdev 884 blocks
a /var/opt/perf/datafiles/logglob 183 blocks
a /var/opt/perf/datafiles/logindx 11 blocks
a /var/opt/perf/datafiles/logpcmd0 1 blocks
a /var/opt/perf/datafiles/logproc 15 blocks
a /var/opt/perf/datafiles/logtran 489 blocks

== Extract Source System Binary Logs ==# /usr/contrib/bin/gzcat /var/tmp/glancelogs.tgz | tar -xvf –
x /var/opt/perf/datafiles/logappl, 17041748 bytes, 33285 tape blocks
x /var/opt/perf/datafiles/logdev, 19638408 bytes, 38357 tape blocks
x /var/opt/perf/datafiles/logglob, 28038808 bytes, 54764 tape blocks
x /var/opt/perf/datafiles/logindx, 46576 bytes, 91 tape blocks
x /var/opt/perf/datafiles/logpcmd0, 15 bytes, 1 tape blocks
x /var/opt/perf/datafiles/logproc, 30438534 bytes, 59451 tape blocks
x /var/opt/perf/datafiles/logtran, 10205840 bytes, 19934 tape blocks

Perform any required reports. See next sections for additional information.

== Clean Binary Logs and Restart OVPA agents ==# rm /var/opt/perf/datafiles/log*

# ls -l /var/opt/perf/datafiles/*
-rw-rw-rw- 1 root sys 31 Nov 23 19:14 /var/opt/perf/datafiles/RUN
-rw-r–r– 1 root root 105 Jul 23 03:18 /var/opt/perf/datafiles/agdb
-rw-r–r– 1 root root 0 Jul 23 03:18 /var/opt/perf/datafiles/agdb.lk
-rw-rw-rw- 1 root root 168 Nov 23 19:15 /var/opt/perf/datafiles/classinfo.db
-rw-r–r– 1 root sys 969354 Nov 23 17:22 /var/opt/perf/datafiles/mikslp.db
# /sbin/init.d/ovpa start

The Perf Agent scope collector is being started.
The ARM registration daemon
/opt/perf/bin/ttd has been started.

The Performance collection daemon
/opt/perf/bin/scopeux has been started.

The coda daemon /opt/OV/lbin/perf/coda has been started.
It will be fully operational in a few minutes.

The Perf Agent alarm generator is being started.
The alarm generator /opt/perf/bin/perfalarm
has been started.
# /opt/perf/bin/perfstat
**********************************************************
*** perfstat for delta on Tue Nov 24 13:28:36 CST 2009
*** HP-UX delta B.11.31 U 9000/800 510254130 unlimited-user license
**********************************************************

list of performance tool processes:
———————————-

Perf Agent status:
Running scopeux (Perf Agent data collector) pid 13766
Running midaemon (Measurement Interface daemon) pid 13778
Running ttd (ARM registration daemon) pid 13760

Perf Agent Server status:

Running ovcd (OV control component) pid 1849
Running ovbbccb (BBC5 communication broker) pid 1860
Running coda (perf component) pid(s) 13798
Running perfalarm (alarm generator) pid(s) 13804

************* (end of perfstat -p output) ****************
# ls -l /var/opt/perf/datafiles/log*
-rw-r–r– 1 root sys 4512 Nov 24 13:28 /var/opt/perf/datafiles/logappl
-rw-r–r– 1 root sys 3836 Nov 24 13:28 /var/opt/perf/datafiles/logdev
-rw-r–r– 1 root sys 3672 Nov 24 13:28 /var/opt/perf/datafiles/logglob
-rw-r–r– 1 root sys 5296 Nov 24 13:28 /var/opt/perf/datafiles/logindx
-rw-r–r– 1 root sys 11 Nov 24 13:28 /var/opt/perf/datafiles/logpcmd0
-rw-r–r– 1 root sys 3672 Nov 24 13:28 /var/opt/perf/datafiles/logproc
-rw-r–r– 1 root sys 4172 Nov 24 13:28 /var/opt/perf/datafiles/logtran

== Global CPU and Memory Utilization ==cat > global_cpumem.rept << EOF REPORT "OVPA Export !DATE !TIME Logfile: !LOGFILE !COLLECTOR !SYSTEM_ID" FORMAT ASCII HEADINGS ON SEPARATOR="|" SUMMARY=60 MISSING=0 DATA TYPE GLOBAL DATE TIME GBL_ACTIVE_CPU GBL_CPU_TOTAL_UTIL GBL_DISK_PHYS_IO_RATE GBL_DISK_PHYS_IO GBL_MEM_FREE GBL_MEM_UTIL GBL_MEM_USER_UTIL GBL_SWAP_SPACE_UTIL GBL_MEM_PAGEOUT_BYTE GBL_MEM_PAGEOUT_BYTE_RATE EOF /opt/perf/bin/extract -g -xp -r global_cpumem.rept \
-f global_cpumem.out,purge \
-b “11/09/2009 08:00:00” -e “11/09/2009 09:00:00”
# cat global_cpumem.out
OVPA Export 11/17/09 16:37 Logfile: /var/opt/perf/datafiles/logglob SCOPE/UX C.04.70.000(0) delta
| |Active| | Phys | Phys | Free |Memory| User | | Pg Out | Pg Out |
Date | Time | CPUs |CPU % | IO Rt | IOs | Mem | % |Mem % |Swap %| KB | KB Rt |
11/09/2009|08:00:00| 7| 56.44| 2519.8| 754932| 15199| 53.49| 40.20| 53.00| 34843| 116.3|
11/09/2009|08:05:00| 7| 42.31| 1968.5| 590746| 14441| 54.85| 41.55| 55.00| 26138| 87.1|
11/09/2009|08:10:00| 7| 50.72| 1491.7| 447062| 13674| 56.43| 43.11| 57.00| 179| 0.6|
11/09/2009|08:15:00| 7| 44.58| 1188.5| 356431| 13022| 57.76| 44.44| 59.00| 479| 1.6|
11/09/2009|08:20:00| 7| 39.02| 880.1| 263941| 12079| 59.30| 45.96| 61.00| 0| 0.0|
11/09/2009|08:25:00| 7| 52.99| 850.4| 255545| 11146| 60.87| 47.53| 63.00| 8353| 27.8|
11/09/2009|08:30:00| 7| 54.77| 898.3| 269759| 10176| 62.65| 49.28| 65.00| 6366| 21.2|
11/09/2009|08:35:00| 7| 42.04| 860.0| 257742| 9186| 64.49| 51.10| 68.00| 0| 0.0|
11/09/2009|08:40:00| 7| 64.83| 1436.1| 430686| 8392| 65.92| 52.52| 70.00| 299| 1.0|
11/09/2009|08:45:00| 7| 56.19| 557.5| 167361| 7772| 67.56| 54.15| 72.00| 60| 0.2|
11/09/2009|08:50:00| 7| 60.21| 569.8| 170996| 6542| 69.52| 56.09| 74.00| 0| 0.0|
11/09/2009|08:55:00| 7| 54.11| 760.1| 228106| 6131| 70.94| 57.46| 76.00| 0| 0.0|

On larger reports, for example when reviewing whole days or weeks, identification of resource bottleneck is better assisted using graphics charts. Data can be ploted to charts imported it to spreadsheets software ot using the GNUplot plugin to plot the required data. For example, to plot the CPU %, Memory % and User Memory % together, the following script can be usedcat > global_cpumem.plot << EOF
set size 1, 0.5
set yrange [0:120]
set xlabel “Samples”
plot ‘-‘ using 1:2 title ‘CPU %’ with lines, \\
‘-‘ using 1:3 title ‘Memory %’ with lines, \\
‘-‘ using 1:4 title ‘User Memory %’ with lines EOF

tail -n $(expr $(wc -l global_cpumem.out | cut -d” ” -f 1) – 3 ) global_cpumem.out | \
awk -F’|’ ‘BEGIN {LINE=1; printf “#Sample\tCPU\tMemory\tUser Memory\n”; } {
printf “%-6d\t%4.2f\t%4.2f\t%4.2f\n”, LINE, $4, $8, $9
LINE++
}’ >> global_cpumem.plot

cat >> global_cpumem.plot << EOF
EOF

cat global_cpumem.plot

The script will provided the required code for the GNUplot to chart the resources.


set size 1, 0.5
set yrange [0:100]
set xlabel “Samples”
plot ‘-‘ using 1:2 title ‘CPU %’ with lines, \
‘-‘ using 1:3 title ‘Memory %’ with lines, \
‘-‘ using 1:4 title ‘User Memory %’ with lines #Sample CPU Memory User Memory
1 50.72 56.43 43.11
2 44.58 57.76 44.44
3 39.02 59.30 45.96
4 52.99 60.87 47.53
5 54.77 62.65 49.28
6 42.04 64.49 51.10
7 64.83 65.92 52.52
8 56.19 67.56 54.15
9 60.21 69.52 56.09
10 54.11 70.94 57.46

== Global Page Out ==export TOP=$(tail -n $(expr $(wc -l global_cpumem.out | cut -d” ” -f 1) – 3 ) global_cpumem.out |
sort -nrk 11,11 | head -n 1 | awk -F”|” ‘{print $11}’)

TOP=$(echo $(( ${TOP} * 110 / 100 )) )

cat > pageout.plot << EOF
set size 1, 0.5
set yrange [0:$TOP]
set xlabel “Samples”
plot ‘-‘ using 1:2 title ‘Pg Out KB’ with lines EOF

tail -n $(expr $(wc -l global_cpumem.out | cut -d” ” -f 1) – 3 ) global_cpumem.out | \
awk -F’|’ ‘BEGIN {LINE=1; printf “#Sample\tPg Out KB\n”; } {
printf “%-6d\t%10d\n”, LINE, $11
LINE++
}’ >> pageout.plot

cat >> pageout.plot << EOF
EOF

The script will provided the required code for the GNUplot to chart the Page Out.


set size 1, 0.5
set yrange [0:38327]
set xlabel “Samples”
plot ‘-‘ using 1:2 title ‘Pg Out KB’ with lines #Sample Pg Out KB
1 34843
2 26138
3 179
4 479
5 0
6 8353
7 6366
8 0
9 299
10 60
11 0
12 0

== Per Process CPU and Memory Utilization ==cat > cpumem.rept << EOF REPORT "OVPA Export !DATE !TIME Logfile: !LOGFILE !COLLECTOR !SYSTEM_ID" FORMAT ASCII HEADINGS ON SEPARATOR="|" SUMMARY=60 MISSING=0 DATA TYPE PROCESS DATE TIME PROC_PROC_ID PROC_PROC_NAME PROC_USER_NAME PROC_CPU_TOTAL_UTIL PROC_MEM_RES PROC_MEM_VIRT EOF /opt/perf/bin/extract -p -xp -r /var/tmp/cpumem.rept \
-f cpumem.out,purge \
-b “11/09/2009 08:00:00” -e “11/09/2009 09:00:00”
# head -n 24 cpumem.out
OVPA Export 11/17/09 17:13 Logfile: /var/opt/perf/datafiles/logglob SCOPE/UX C.04.70.000(0) delta
| | | Process | User | | Res |Virtual |
Date | Time | PID | Name | Name | CPU % | Mem | Memory |
11/09/2009|08:00:00| 78|vxfsd |root | 2.05| 38912| 44032|
11/09/2009|08:00:00| 4975|oracleV24P |oracle | 71.14| 41984| 53248|
11/09/2009|08:00:00| 25409|ora_j000_UNIC |oracle | 0.03| 13572| 15880|
11/09/2009|08:00:00| 25153|oraclePAM |oracle | 1.04| 11784| 25576|
11/09/2009|08:00:00| 25393|oraclePAM |oracle | 3.00| 304| 1344|
11/09/2009|08:00:00| 24972|compress |oracle | 15.21| 784| 808|
11/09/2009|08:00:00| 25188|compress |oracle | 54.92| 848| 872|
11/09/2009|08:00:00| 25365|ora_m000_PAM |oracle | 2.08| 14740| 28192|
11/09/2009|08:00:00| 17482|oracleSCHD |oracle | 12.15| 27240| 50176|
11/09/2009|08:00:00| 3138|ora_dbw0_UNIC |oracle | 0.00| 15752| 54272|
11/09/2009|08:00:00| 3266|ora_lgwr_SCHD |oracle | 0.00| 24060| 489472|
11/09/2009|08:00:00| 3621|ora_lgwr_PLIN |oracle | 0.00| 16436| 34816|
11/09/2009|08:00:00| 24581|oracleV24P |oracle | 57.21| 26812| 30536|
11/09/2009|08:00:00| 19689|ftpd |root | 2.12| 1828| 2584|
11/09/2009|08:01:00| 78|vxfsd |root | 3.08| 38912| 44032|
11/09/2009|08:01:00| 4975|oracleV24P |oracle | 56.80| 44032| 52224|
11/09/2009|08:01:00| 25486|oracleSCHD |oracle | 13.37| 25980| 34816|
11/09/2009|08:01:00| 25409|ora_j000_UNIC |oracle | 9.33| 16636| 20824|
11/09/2009|08:01:00| 3140|ora_lgwr_UNIC |oracle | 0.00| 16000| 72704|
11/09/2009|08:01:00| 25447|cimprovagt |root | 0.00| 1248| 2056|
11/09/2009|08:01:00| 3250|ora_dbw2_SCHD |oracle | 0.00| 25476| 55296|

== Per Process CPU and I/O Utilization ==cat > cpuio.rept << EOF REPORT "OVPA Export !DATE !TIME Logfile: !LOGFILE !COLLECTOR !SYSTEM_ID" FORMAT ASCII HEADINGS ON SEPARATOR="|" SUMMARY=60 MISSING=0 DATA TYPE PROCESS DATE TIME PROC_PROC_ID PROC_PROC_NAME PROC_USER_NAME PROC_CPU_TOTAL_UTIL PROC_DISK_PHYS_IO_RATE PROC_IO_BYTE_RATE PROC_DISK_FS_IO PROC_DISK_VM_IO PROC_DISK_SYSTEM_IO EOF /opt/perf/bin/extract -p -xp -r /var/tmp/cpuio.rept \
-f cpuio.out,purge \
-b “11/09/2009 08:00:00” -e “11/09/2009 09:00:00”
# head -n 24 cpuio.out
| | | Process | | Phys | IO Byte |File System| VM | System |
Date | Time | PID | Name | CPU % |IO Rt | Rate | IOs | IOs | IOs |
03/16/2010|11:00:00| 129|vxfsd | 0.04| 20.4| 147.0| 1138| 0| 110|
03/16/2010|11:00:00| 29798|dw.sapCP1_D33 | 10.06| 0.0| 0.0| 0| 0| 0|
03/16/2010|11:00:00| 8082|dw.sapCP1_D33 | 17.10| 0.1| 0.2| 6| 0| 0|
03/16/2010|11:00:00| 25418|dw.sapCP1_D33 | 25.17| 0.0| 0.1| 0| 0| 0|
03/16/2010|11:00:00| 26554|dw.sapCP1_D33 | 20.09| 0.0| 0.0| 0| 0| 0|
03/16/2010|11:00:00| 11052|dw.sapCP1_D33 | 18.14| 0.0| 0.0| 0| 0| 0|
03/16/2010|11:00:00| 29794|dw.sapCP1_D33 | 16.14| 0.0| 0.0| 0| 0| 0|
03/16/2010|11:00:00| 8902|jlaunch | 0.01| 0.0| 0.0| 0| 0| 0|
03/16/2010|11:00:00| 28575|dw.sapCP1_D33 | 13.14| 0.0| 0.0| 0| 0| 0|
03/16/2010|11:00:00| 22427|icman | 38.48| 0.6| 16.0| 0| 0| 36|
03/16/2010|11:00:00| 8903|jlaunch | 0.01| 0.0| 0.0| 0| 0| 0|
03/16/2010|11:00:00| 29516|dw.sapCP1_D33 | 44.42| 0.0| 0.0| 0| 0| 0|
03/16/2010|11:00:00| 29801|dw.sapCP1_D33 | 19.09| 0.0| 0.0| 0| 0| 0|
03/16/2010|11:00:00| 29793|dw.sapCP1_D33 | 14.20| 0.0| 0.0| 0| 0| 0|
03/16/2010|11:00:00| 29804|dw.sapCP1_D33 | 11.06| 0.0| 0.0| 0| 0| 0|
03/16/2010|11:00:00| 8189|dw.sapCP1_D33 | 36.30| 0.0| 0.0| 0| 0| 0|
03/16/2010|11:00:00| 29796|dw.sapCP1_D33 | 20.12| 0.0| 0.0| 0| 0| 0|
03/16/2010|11:00:00| 29792|dw.sapCP1_D33 | 19.10| 0.0| 0.0| 0| 0| 0|
03/16/2010|11:01:00| 129|vxfsd | 0.03| 10.4| 93.0| 583| 0| 35|
03/16/2010|11:01:00| 8082|dw.sapCP1_D33 | 10.04| 0.0| 0.0| 0| 0| 0|
03/16/2010|11:01:00| 25418|dw.sapCP1_D33 | 20.11| 0.0| 0.0| 0| 0| 0|

== Reference ==
* [[How to collect glance binary log files]]
* [[How to create performance statistics charts]]

== Authors ==
* [[Alejandro Marin Badilla]]

[[Category:HP-UX]]
[[Category:Performance]]