How to interpret output of "debug dataplane pow performance" during troubleshooting high DP CPU

How to interpret output of "debug dataplane pow performance" during troubleshooting high DP CPU

33921
Created On 12/31/18 06:45 AM - Last Modified 05/01/19 20:49 PM


Objective
The SSO (Schedule/ Synchronisation/ Order) unit is the component of the Dataplane which manages packet scheduling and ordering. It is also known as POW (Packet / Order / Work). It is responsible for scheduling work to cores based on QOS Priority and Work Groups. It also maintains packet ingress order.

A work group is a set of applications and each core can be assigned to more than one work group. Work groups are used to balance the processing load among the different cores. The work group value of a packet is set automatically on ingress, and can be changed by software. 

This article covers some pointers how to interpret pow performance data.

 


Environment
This output is common to all PAN-OS firewalls either hardware or virtual.

Procedure
The output of "debug dataplane pow performance" gives a brief idea of usage of each work group and DP function in the last sampling cycle:
  1. How many number of times a work group and function was scheduled.
  2. What was the average processing time in microseconds (us) for each work groups and function.
  3. What was the maximum processing time in microseconds (us) for each work groups and function.
Sample output:
 
User-added image

Column 1: Work Group [or DP Function] Name
Column 2: Max Processing Time for this work group in the last sampling cycle
Column 3: Average Processing Time for this work group in the last sampling cycle
Column 4: Count of times this work group [or DP Function] was scheduled

Explanation of workgroups:
 
flow_np             : Network Processor. Very first program to decide if it is slow path or fast path.
flow_lookup         : Responsible for existing session/flow lookup.
flow_mgmt           : Installation and clearing of session table.
flow_fastpath       : Fastpath processing of packet (Includes post slowpath processing and content inspection).
flow_slowpath       : Slow path processing of packet (route and policy lookup and session setup).      
flow_forwarding     : Handles forwarding stage of packets.
dfa_result          : Appid signature matching           
module_internal     : Control messages between internal components .        
aho_result          : Threat signature matching.
zip_result          : Used for ZIP processing.
pktlog_forwarding   : Responsible for forwarding logs to MP.
flow_host           : Process handling packets destined to Firewall
flow_ctrl           : Aging sessions and handling net-messages 
nac_result          : Analyzing result of appid  signature match output

The above output gives us very necessary insight into the usage on DP.
  1. Relative values of count gives us an idea of which work group or function is being called for more number of times.
  2. In general processing flow_slowpath would have smaller count compared to flow_fastpath.  If we compare this data historically from dp-monitor log file, we can see if the count for any particular work group has increased in a specific time window.
  3. module_internal is used for control messages between internal components like URL Lookups etc. A high count of module_internal may indicate a lot of internal messaging.
  4. In general count for flow_fastpath, flow_forwarding, flow_np should be invoked for each transit traffic. So their count will be comparably high.
  5. aho_result, dfa_result, nac_result would give us an idea of amount of Layer 7 going on the firewall.
  6. A high value of Max Proc us is fine, but a high value of ave. proc us is not good.
    NOTE: We can multiply count with ave proc us for each work group to get an idea of which work group is using most CPU time.
  7. When things look normal from work groups stand point and still DP CPU is under load, we should move on to inspect the functions to understand which function is using how much CPU.


Additional Information
Case Study:

For example, CPU is 100% and workgroups look as below:
 
:group                max. proc us     ave. proc us     count           
:flow_lookup          0                0                0               
:flow_fastpath        122087           55               33971601        
:flow_slowpath        199              72               345516          
:flow_forwarding      75               2                8910565         
:flow_mgmt            57               29               69              
:flow_ctrl            100              6                302011          
:nac_result           50               1                2015416         
:flow_np              66               4                33255061        
:dfa_result           21794            242              2059391         
:module_internal      525              18               173530          
:aho_result           119981           154              2014275         
:zip_result           16771            234              197454          
:pktlog_forwarding    84               7                287854          
:lwm                  0                0                0               
:flow_host            52               11               5494

We know from above that fastpath is highest, but to find reason of which component is using more CPU lets look at the functions for the same:
 
:func                                     max. proc us     ave. proc us     count    
      
:dfa_match                                0                0                0               
:policy_lookup                            125              10               2239062         
:user_group_policy                        87               1                477903          
:get_gid                                  41               0                1061755         
:regex_lookup                             6217             102              2233481         
:regex_postfpga                           910              16               1039761         
:reg_expr_match                           0                0                0               
:sml_vm                                   208              6                31643903        
:detector_run_p1                          2342             34               906163          
:detector_run_p2                          31327            79               889286          
:ssl_proxy_proc                           63072            600              2500540         
:ssl_encode                               202              36               805522          
:rsa_operation_pub_enc                    766              309              6688            
:rsa_operation_pub_dec                    648              263              116             
:rsa_operation_priv_enc                   8216             8168             14362           
:rsa_operation_priv_dec                   8260             8178             6427            
:rsa_key_gen                              40126            23467            43              
:rsa_RSA_sign                             13840            13236            33704           
:rsa_RSA_verify                           963              430              71904           
:ecdhe_key_gen                            22925            7559             18              
:ecdhe_key_gen_mul                        0                0                0               
:ecdhe_key_compute_mul                    22121            6640             82229           
:ecdhe_key_compute                        22565            6856             82224           
:ecdhe_generate_xchg_key                  23514            7948             18              
:ecdhe_gen_key_exchange_msg               22630            6949             43919           
:ecdhe_get_key_exchange_msg               22656            6932             38261           
:ecdhe_parse_server_key_exchange_msg      320              244              45817           
:ecdhe_gen_server_key_exchange_msg        78               29               43561           
:dhe_gen_para                             0                0                0               
:dhe_gen_key                              0                0                0               
:dhe_key_compute                          0                0                0               
:bn_mod_exp                               8226             6196             27618           
:cipher_enc                               142              9                1956671         
:zip_deflate                              50               2                197543          
:pktlog_log                               0                0                0               
:pktlog_send                              0                0                0               
:tunnel_encap                             0                0                0               
:tunnel_decap                             0                0                0               
:tunnel_esp                               0                0                0               
:tunnel_esp_decap                         0                0                0               
:tunnel_ah_decap                          0                0                0               
:tunnel_ah                                0                0                0               
:tunnel_fwd                               0                0                0               
:tunnel_prepare                           0                0                0               
:tunnel_post                              0                0                0               
:appid_result                             0                0                0               
:ctd_token                                21789            239              2060687         
:dos_update                               17               0                212713          
:urlcache_update                          20065            178              2555            
:urlcache_lookup                          107402           125              540508          
:urlcache_insert                          0                0                0               
:urlcache_delete                          0                0                0               
:urlcache_lru                             0                0                0               
:session_install                          59               8                217532          
:session_age                              36               0                875144          
:session_delete                           165              11               212717          
:session_purge                            0                0                0               
:inline_switch                            0                0                0               
:age_arp                                  20               2                595             
:age_pbf_ret_mac                          1                0                595             
:stack_trace                              0                0                0               
:ctd_pw_check                             0                0                0               
:ctd_pw_md4                               0                0                0               
:ctd_pw_extract                           0                0                0               
:prl_rewrite                              0                0                0               
:pkt_rewrite                              0                0                0               
:vpn_send_to_client                       0                0                0               
:vpn_cookie_response                      0                0                0               
:raven_match                              46               2                131751          
:raven_match_header                       52               2                187227          
:raven_match_body                         51               14               6               
:raven_sig_get_action                     0                0                0               
:age_mfib                                 1                0                595

In above, if you multiply the count by average time, you can get a clear idea of what is using most CPU. For example see below (output truncated only for top used functions)
 
:func                                    max. proc us     ave. proc us     count       count*avg     

:ssl_proxy_proc                          63072            600              2500540     1500324000   
:ecdhe_key_compute                       22565            6856             82224       563727744    
:ecdhe_key_compute_mul                   22121            6640             82229       546000560    
:ctd_token                               21789            239              2060687     492504193    
:rsa_RSA_sign                            13840            13236            33704       446106144    
:ecdhe_gen_key_exchange_msg              22630            6949             43919       305193131    
:ecdhe_get_key_exchange_msg              22656            6932             38261       265225252    
:regex_lookup                            6217             102              2233481     227815062
:sml_vm                                  208              6                31643903    189863418
:bn_mod_exp                              8226             6196             27618       171121128
:rsa_operation_priv_enc                  8216             8168             14362       117308816
:detector_run_p2                         31327            79               889286      70253594
:urlcache_lookup                         107402           125              540508      67563500
:rsa_operation_priv_dec                  8260             8178             6427        52560006
:rsa_RSA_verify                          963              430              71904       30918720
:detector_run_p1                         2342             34               906163      30809542
:ssl_encode                              202              36               805522      28998792
:policy_lookup                           125              10               2239062     22390620
:cipher_enc                              142              9                1956671     17610039
:regex_postfpga                          910              16               1039761     16636176
:ecdhe_parse_server_key_exchange_msg     320              244              45817       11179348

You can see most of the top used functions are related to SSL decryption. So this gives us a good idea of what further steps to take alleviate this.


Actions
  • Print
  • Copy Link

    https://knowledgebase.paloaltonetworks.com/KCSArticleDetail?id=kA10g000000CmV2CAK&refURL=http%3A%2F%2Fknowledgebase.paloaltonetworks.com%2FKCSArticleDetail

Attachments