Understanding CPU Usage and Session Data Statistics from log.sipd

Asset ID:	1-71-1591859.1
Update Date:	2017-04-11
Keywords:

Solution Type Technical Instruction Sure

Solution 1591859.1 : Understanding CPU Usage and Session Data Statistics from log.sipd

Applies to:

Acme Packet 4500 - Version S-Cx6.0.x and later
Acme Packet 3820 - Version S-Cx6.0.x and later
Net-Net 3810 - Version S-Cx6.0.x and later
Acme Packet OS

Goal

How to understand CPU usage and session data statistics from log.sipd

Solution

Example entries from log.sipd

Oct 16 07:28:03.003 [SIP] CPU=60390.186: cur=100(95) avg=42 in 130003

Oct 16 07:28:23.000 [SIP] SES[R=606/4479/1817 T=845230/2501/2032]

CPU=60390.186 – Total CPU usage in ticks of the sipd task since bootup.

cur=100(95) – Current CPU is at 100 with a threshold of 95

avg=42 in 130003 – Average CPU is 42.

SES[R=606/4479/1817 – current sessions/ current window + previous window / Max in this window

T=845230/2501/2032 – Absolute sessions / max prev+current sessions / max sessions in any window.

This is an explanation of the log.sipd output lines:

Jul 4 09:36:17.329 [SIP] SES[R=525/2176/555 T=30584/2228/566]
Jul 4 09:36:17.330 [SIP] cur=21.7 lo=20.6 hi=23.6 avg=22.7 (90%=39.0)
Jul 4 09:36:17.330 [SIP] ST[R=3841/12395/3901 T=362439/12536/3912] rate=12.3
Jul 4 09:36:17.330 [SIP] CT[R=1643/11192/1694 T=322650/11275/1694] rate=11.1
Jul 4 09:36:17.330 [SIP] REG[45057/45057] new=0 fwd=745 ref=31 tmo=0 post=0 ext=0SurReg[0/0] newSurReg=0 SurRegSent=0SurRegTmo=0
Jul 4 09:36:17.330 [SIP] CPU=1180.609: cur=52 avg=50 in 60.000

[SIP] SES[R=900/499/937 T=79886/450/1035]

this line matches output from "show session"
- Active/High/Total and Total/PerMax/High

ACME-sd1# show sess
14:40:16-146 Capacity=32000
Session Statistics -- Period -- -------- Lifetime --------
Active High Total Total PerMax High
Total Sessions 0 0 0 0 0 0

[SIP] cur=4.1 lo=3.6 hi=4.4 avg=3.6 (90%=27.9)

This line is current calls per second (CPS) rate. The value in parenthesis is an extrapolation of how many CPS you should expect the system to perform if the CPU were at 90% utilization (estimate only).

[SIP] CPU=1317064.169: cur=13 avg=12 in 60.001

this line roughly matches output from "show proc cpu"
CPU= is the usage since boot, current is the current CPU usage %, avg is the average CPU usage %

Jul 4 09:36:17.330 [SIP] ST[R=3841/12395/3901 T=362439/12536/3912] rate=12.3

- Matches top line of output of ‘show sip server’
Active / Period High / Period total, lifetime Total / Lifetime Period Max / and Lifetime High

Anvil-sd1# show sip server
14:40:39-169
SIP Server Trans -- Period -- -------- Lifetime --------
Active High Total Total PerMax High
All States 0 0 0 0 0 0

Jul 4 09:36:17.330 [SIP] CT[R=1643/11192/1694 T=322650/11275/1694] rate=11.1

- matches top line of output of ‘show sip client’
Active / Period High / Period total, lifetime Total / Lifetime Period Max / and Lifetime High

Anvil-sd1# show sip client
14:40:49-179
SIP Client Trans -- Period -- -------- Lifetime --------
Active High Total Total PerMax High
All States 0 0 0 0 0 0

Jul 4 09:36:17.330 [SIP] REG[45057/45057] new=0 fwd=745 ref=31 tmo=0 post=0 ext=0SurReg[0/0] newSurReg=0 SurRegSent=0SurRegTmo=0

REG [User Entries Active / User Entries Period High] Forwards, refreshes, timeouts, fwd postponed, refresh extended, surrogate regs, surrogate reg sent, surrogate reg timeouts

Anvil-sd1# show reg
14:41:02-192
SIP Registrations -- Period -- -------- Lifetime --------
Active High Total Total PerMax High
User Entries 0 0
…………………………
Forwards - - 0 0 0
Refreshes - - 0 0 0
Rejects - - 0 0 0
Timeouts - - 0 0 0
Fwd Postponed - - 0 0 0
…………………..
Refresh Extended - - 0 0 0
Surrogate Regs 0 0 0 0 0 0
Surrogate Sent - - 0 0 0
……….
Surrogate Timeout - - 0 0 0

****UPDATE 04/11/2017****

As of 7.x release, please note that the server and client transaction report information has been removed from the logs. The rest of the information still pertains.

Attachments

This solution has no attachment