Instructions

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 packet engine's (PE) associated CPU exceeds 90% utilization, the profiler captures the data into a set of files in newproflog_cpu_<cpu-id>.out.

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_microseconds>
                      | lctidle=<time_in_microseconds> | lctbsd=<time_in_microseconds> | lcttimer=<time_in_microseconds> | lcttimerexec=<time_in_microseconds>
                      | lctoutnetio=<time_in_microseconds> | 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
• time - time (in seconds) to capture the profiler data before restarting a new capture
• loop - number of iterations of the profiler captures

• 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

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
• kernelhits - display hits symbols for kernel profile data captured for specific cpu-id from capture file e.g newproflog_cpu_<cpu-id>.out
• ppehits - display hits symbols for PPE profile data captured for specific cpu-id from capture file e.g newproflog_cpu_<cpu-id>.out
• aggrhits - display aggregated hits symbol for combined kernel and PPE 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

Note: 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
==============================================================================

8. Once All data is collected we need to revert back the profiler settings, i.e leave it running at 90% threshold. If this step is skipped, continuous profiling wont happen till next reboot.

nohup /usr/bin/bash /netscaler/nsproflog.sh cpuuse=900 start &

Verify the following, note the the last line will repeat for each packet cpu.

root@ns# ps -aux | grep -i prof
root       2946  0.0  0.0  1532   984  ??  Ss   12:27PM   0:00.00 /netscaler/nsprofmgmt 90.0
root       2920  0.0  0.1  5132  2464   0  S    12:27PM   0:00.02 /usr/bin/bash /netscaler/nsproflog.sh cpuuse=900 start
root       2957  0.0  0.1 46564  4376   0  R    12:27PM   0:00.01 /netscaler/nsprofmon -s cpu=1 -ys cpuuse=900 -ys profmode=cpuuse -O -k /var/nsproflog/newproflog_cpu_1.out -s logsize=10485760 -ye capture