netscaler high CPU during load test - cpu profiling help

NetScaler Profiler Help page

Updated for nCore platforms

1. Profiler Scripts

nsproflog.sh - This script is used to start/stop??NetScaler??Profiler??

2. Profiler directory path

/var/nsproflog - All profiler related captured data/or scripts resides in this directory??

3. Constant Profiling

On??NetScaler, at the boot time, the profiler is invoked and it keeps running. At any time if any of the PE's associated CPU exceeds 90% utilization, the profiler captures the data into a set of files in newproflog_cpu_<cpu-id>.out. For detail information, refer to??ConstantProfiling

4. Help Usage

root@ns# /netscaler/nsproflog.sh -h??
nCore Profiling??
nsproflog - utility to start/stop??NetScaler??profiler to capture data and to display the profiled data??
usage: nsproflog.sh [-h] [cpu=<cpu-id>] [cpuuse=<cpu_utilization_in_percentage*10> | lctnetio=<time_in_us>??

• | lctidle=<time_in_us> | lctbsd=<time_in_us> | lcttimer=<time_in_us> | lcttimerexec=<time_in_us>??
  | lctoutnetio=<time_in_us> | time=<time_in_seconds>] [loop=<count>] [hitperc=<value_in_percentage>]??

• [display=<capture_file_path>] [kernel=<nsppe_file_path>] [start | stop]??

• -h - print this message - exclusive option

Options used for starting the profiler:??

• start - start the capture??
  cpu - cpu-id on which profiler needs to capture data, default: on all cpus??
  cpuuse - threshold value (in cpu_percentage*10) when cpu utilization exceeds above this will trigger profiler to start capturing data in newproflog_cpu_<cpu-id>.out??
  lct* - help to find Lost CPU Time (in microseconds), when CPU cycles are spent for longer duration in functions other than packet processing

  • LCT have following options:

    • lctidle - Amount of time spent in idle function
      lctnetio - Amount of time spent in netio
      lcttimer - Amount of timer HA timer is not called
      lcttimerexec - Amount of time spent in executing??NetScaler??timeout functions e.g pe_dotimeout etc
      lctbsd - Amount of time spent in freebsd
      lctoutnetio - Amount of time spent since netio is called again

  time - time (in seconds) to capture the profiler data before restarting a new capture
  loop - number of iterations of the profiler captures

Options used for displaying the profiler data:

• hitperc - hit percentage threshold for displaying functions with Hitratio (Number of hits for the function in percentage)

  • above the threshold, default: 1%

  display - display profiled data captured for specific cpu-id from capture file e.g newproflog_cpu_<cpu-id>.out kernel -??NetScaler??nsppe file path, default: /netscaler/nsppe

Options used for stopping the profiler:

• cpu - cpu-id on which profiler needs to be stopped, default: on all cpus stop - stop the capture and generate a .tar.gz file for the captured outputs

Examples: :
To start the profiler with a threshold above 70% cpu utilization to capture data on all the cpus??
nsproflog.sh cpuuse=700 start??

To start the profiler with capture when lost cpu time exceeds 2 milliseconds inside idle functions??
nsproflog.sh lctidle=2000 start??

To stop the profiler and generate the .tar.gz of all captured data??
nsproflog.sh stop??

To display captured data for all function with Hitratio > 1%??
nsproflog.sh display=/var/nsproflog/newproflog.0/newproflog_cpu_1.out??

To display captured data for all function with Hitratio > 0%??
nsproflog.sh hitperc=0 display=/var/nsproflog/newproflog.0/newproflog_cpu_1.out kernel=/netscaler/nsppe??

Notes:??
If another instance of profiler is already running, then please stop the current profiler,??
before running the new instance of profiler with a different CPU threshold??

5. To start the profiler with no CPU threshold to capture data on all the cpu's??

root@ns# /netscaler/nsproflog.sh start &??
[1] 65065??
root@ns# nCore Profiling??
Setting (512 KB) of profile buffer for cpu 3 ... Done.
Setting (512 KB) of profile buffer for cpu 2 ... Done.
Setting (512 KB) of profile buffer for cpu 1 ... Done.
Collecting profile data for cpu 3
Collecting profile data for cpu 2
Capturing profile data for 10 seconds...
Collecting profile data for cpu 1
Capturing profile data for 10 seconds...
Please wait for profiler to capture data
Capturing profile data for 10 seconds...
root@ns# root@ns# root@ns# Saved profiler capture data in newproflog.9.tar.gz
Collecting profile data for cpu 3
Collecting profile data for cpu 2
Capturing profile data for 10 seconds...
Collecting profile data for cpu 1
Capturing profile data for 10 seconds...
Please wait for profiler to capture data
Capturing profile data for 10 seconds...
root@ns#cd /var/nsproflog??
root@ns#pwd??
/var/nsproflog??
root@ns# ls -ll
total 9356??
-rw-r--r-- 1 root wheel 109423 Sep 24 22:37 newproflog.0.tar.gz
-rw-r--r-- 1 root wheel 156529 Sep 24 22:38 newproflog.1.tar.gz
-rw-r--r-- 1 root wheel 64410 Sep 24 22:38 newproflog.2.tar.gz
-rw-r--r-- 1 root wheel 111448 Sep 24 22:38 newproflog.3.tar.gz
-rw-r--r-- 1 root wheel 157538 Sep 24 22:38 newproflog.4.tar.gz
-rw-r--r-- 1 root wheel 65603 Sep 24 22:38 newproflog.5.tar.gz
-rw-r--r-- 1 root wheel 112944 Sep 24 22:38 newproflog.6.tar.gz
-rw-r--r-- 1 root wheel 158081 Sep 24 22:39 newproflog.7.tar.gz
-rw-r--r-- 1 root wheel 44169 Sep 24 22:39 newproflog.8.tar.gz
-rw-r--r-- 1 root wheel 48806 Sep 25 22:19 newproflog.9.tar.gz
-rw-r--r-- 1 root wheel 339 Sep 16 23:16 newproflog.old.tar.gz
-rw-r--r-- 1 root wheel 208896 Sep 25 22:19 newproflog_cpu_1.out
-rw-r--r-- 1 root wheel 208896 Sep 25 22:19 newproflog_cpu_2.out
-rw-r--r-- 1 root wheel 208896 Sep 25 22:19 newproflog_cpu_3.out
-rw-r--r-- 1 root wheel 6559889 Sep 18 21:43 newproflog_mgmtcpu
-rw-r--r-- 1 root wheel 202630 Sep 18 05:58 newproflog_mgmtcpu.0.gz
-rw-r--r-- 1 root wheel 3 Sep 25 22:19 nsproflog.nextfile
-rw-r--r-- 1 root wheel 309 Sep 25 22:19 nsproflog_args
-rw-r--r-- 1 root wheel 1 Sep 25 22:18 nsproflog_options
-rw-r--r-- 1 root wheel 6 Sep 25 22:18 ppe_cores.txt

6. To stop the profiler on all the cpus

root@ns# /netscaler/nsproflog.sh stop??
nCore Profiling??
Stopping all profiler processes
Killed
Killed
Killed
Removing buffer for -s cpu=3
Removing profile buffer on cpu 3 ... Done.
Removing buffer for -s cpu=2
Removing profile buffer on cpu 2 ... Done.
Removing buffer for -s cpu=1
Removing profile buffer on cpu 1 ... Done.
Saved profiler capture data in newproflog.0.tar.gz
Stopping mgmt profiler process
[1]+ Killed: 9 /netscaler/nsproflog.sh start
root@ns#??

7. To display the profiled data on cpu#1 with no CPU threshold for all the function whose Hitratio% is greater than default threshold hitperc=1

root@ns# tar -xzvf newproflog.9.tar.gz??
newproflog.9/
newproflog.9/newproflog_cpu_1.out
newproflog.9/newproflog_cpu_2.out
newproflog.9/newproflog_cpu_3.out
newproflog.9/nsproflog_args
root@ns# cd newproflog.9
root@ns# ls
newproflog_cpu_1.out newproflog_cpu_2.out newproflog_cpu_3.out nsproflog_args
root@ns#
root@ns# /netscaler/nsproflog.sh display=newproflog_cpu_1.out??
nCore Profiling
Displaying the profiler command-line arguments used during start of capture
/netscaler/nsproflog.sh
/netscaler/nsprofmon -s cpu=3 -O -k /var/nsproflog/newproflog_cpu_3.out -T 10 -ye capture
/netscaler/nsprofmon -s cpu=2 -O -k /var/nsproflog/newproflog_cpu_2.out -T 10 -ye capture
/netscaler/nsprofmon -s cpu=1 -O -k /var/nsproflog/newproflog_cpu_1.out -T 10 -ye capture
Displaying the profile capture statistics for proc with??HitRatio??> 1%??
NetScaler??NS11.0: Build 13.6.nc, Date: Sep 18 2013, 13:54:47??
==============================================================================
Index??HitRatio??Hits??TotalHit% Length Symbol name
==============================================================================
1 50.358% 5550 50.358% 1904 packet_engine**
2 15.380% 1695 65.738% 32 pe_idle_readmicrosec**
3 9.037% 996 74.775% 112 nsmcmx_is_pending_messages**
4 8.956% 987 83.731% 80 vc_idle_poll**
5 7.041% 776 90.772% 96 vmpe_intf_loop_rx_any**
6 6.143% 677 96.915% 256 vmpe_intf_e1k_sw_rss_tx_any**
7 1.370% 151 98.285% 64 vmpe_intf_e1k_rx_any**
==============================================================================
8 98.285% 11021??
==============================================================================

** - Idle Symbols??
Displaying the summary of proc hits.................................
==============================================================================

• PID PROCNAME PROCHIT PROCHIT%

==============================================================================

• 1326 NSPPE-00 11021 100.00

==============================================================================
root@ns#??