Description

Oinker logs may be reported by an FPC carrying subscribers. 

Routing-engine CPU typically is not high (such as 78% idle, which is 22% utilized), but the FPC CPU utilization was above 80%, spiking to 95 or 100% occasionally. 

Symptoms

Logs similar to these might be seen: 

Feb 11 20:02:04  MX960_RE0 fpc5 Oinker: Function Packet Transfer Periodic (0x10cd4000) took 220 us
Feb 11 20:33:05  MX960_RE0 fpc5 Oinker: Function Packet Transfer Periodic (0x10cd4000) took 337 us
Feb 11 20:35:34  MX960_RE0 fpc5 Oinker: Function MPC (0x1005ebfc) took 204 us
Feb 11 20:36:34  MX960_RE0 fpc5 Oinker: Function Packet Transfer Periodic (0x10cd4000) took 437 us

Feb 11 20:50:48  MX960_RE0 fpc5 Oinker: Function Syslog (0x100925f8) took 415 us

Oinker logs are Emergency level, so they may print to the router Admin's ssh or telnet session if any logs are configured to print to the router admin's ssh and telnet sessions. That configuration area is "system syslog user *". For example, with the following config, Oinker logs will be printed to a router admin's ssh session:

labuser@MX960_RE0# show system syslog user * | display set
set system syslog user * any emergency​

Solution

Packet Transfer Periodic  is a function that checks the health of the Packet Transfer Engine periodically by ensuring that it has not undergone any wedge. Oinker is a check that is introduced to ensure that the periodic functions are executed quickly, this time is set at 200usec. If the CPU spends greater than 200usec, then a message is logged in the messages indicating the same.

These logs may not be a root cause; they can be a symptom of high resource utilization on an FPC, such as high CPU. 

Check " show chassis fpc " to see if the FPC reporting these logs has high CPU, such as the 84% CPU below: 

labuser@MX960_RE0> show chassis fpc 5
                     Temp  CPU Utilization (%)   CPU Utilization (%)  Memory    Utilization (%)
Slot State            (C)  Total  Interrupt      1min   5min   15min  DRAM (MB) Heap     Buffer        
  5  Online            54     84         55       84     84     84    3584        9         25


This type of output can assist in determining if the Oinker logs correlate with a DDOS violation. Below, we see a DDOS_PROTOCOL_VIOLATION_SET log for protocol/exception  ARP:aggregate shortly before the Oinker logs starts. There were no Oinker logs that day prior to the DDOS violation. 

labuser@MX960_RE0> show log messages | match "DDOS|Oinker" | match "fpc5|fpc 5" | find "Feb 11"
Feb 11 19:51:38  MX960_RE0 jddosd[5127]: DDOS_PROTOCOL_VIOLATION_SET: Warning: Host-bound traffic for protocol/exception  
ARP:aggregate exceeded its allowed bandwidth at fpc 5 for 1 times, started at 2019-02-11 19:51:36 UTC
Feb 11 20:02:04  MX960_RE0 fpc5 Oinker: Function Packet Transfer Periodic (0x10cd4000) took 220 us
Feb 11 20:33:05  MX960_RE0 fpc5 Oinker: Function Packet Transfer Periodic (0x10cd4000) took 337 us
Feb 11 20:35:34  MX960_RE0 fpc5 Oinker: Function MPC (0x1005ebfc) took 204 us

In this example, the subscriber's subinterface was disabled. Then the FPC5 CPU dropped to between 22% and 32% utilization, and the Oinker logs stopped.

labuser@MX960_RE0> show chassis fpc 5  
                     Temp  CPU Utilization (%)   CPU Utilization (%)  Memory    Utilization (%)
Slot State            (C)  Total  Interrupt      1min   5min   15min  DRAM (MB) Heap     Buffer
  5  Online            55     22          1       21     22     22    3584        9         25


Please contact your JTAC representative for assistance to determine which subscriber subinterface may be causing the ARP flood. The subscriber's subinterface can be disabled until the issue can be corrected on the subscriber's CPE (Customer Permises Equipment).

Examine " show ddos-protection protocols arp " to see the maximum packet arrival rate, and what levels are configured to trigger a ddos-protection violation. 

Modification History

2020-06-02: Added explanation for the terms, "Packet Transfer Periodic" and "Oinker" in the Cause section.