Network latency increase after a certain time

The name of the pictureThe name of the pictureThe name of the pictureClash Royale CLAN TAG#URR8PPP











up vote
0
down vote

favorite












I have an ubuntu 14.04, low-latency kernel, installed on an upboard machine. I'm using this machine for very low latency application (i.e. LTE). Briefly, this machine gets some packets on the Ethernet interface, which are retransmitted on a USRP radio interface through USB 3.0. Every thing goes fine, but after a certain time (close to 5:30 minutes), the delay significantly increases, which disturbs a lot the application.



I disabled all CPU power management, and CPUs frequency are on the maximum. I can't see if the frame RX time is increased on Ethernet, or in the contrary if the TX increases on USB 3.0. Nevertheless, this seems to be occurring at exactly the same time.



Edit:



I ran a perf on the kernel using: 



perf record -F 99 -a -- sleep 60


This is totally new for me, but it does not seem to be anything different between before/after the problem occurs. Here are the results:



Before: 



# Overhead Command Shared Object Symbol 
# ........ ............... ......................... ...............................
#
 61.47% swapper [kernel.kallsyms] [k] cpu_startup_entry
 2.28% lte-softmodem.R lte-softmodem.Rel14 [.] idft64
 1.89% lte-softmodem.R lte-softmodem.Rel14 [.] PHY_ofdm_mod
 1.21% ru_thread_FH 0 liboai_usrpdevif.so [.] _ZL13trx_usrp_readP17openai
 1.11% lte-softmodem.R [kernel.kallsyms] [k] copy_user_enhanced_fast_str
 0.90% lte-softmodem.R lte-softmodem.Rel14 [.] dft256
 0.76% lte-softmodem.R lte-softmodem.Rel14 [.] idft256
 0.73% ru_thread_FH 0 libpthread-2.23.so [.] pthread_mutex_unlock
 0.70% ru_thread_FH 0 [kernel.kallsyms] [k] pick_next_task_fair
 0.70% ru_thread_FH 0 libuhd.so.003.010 [.] 0x000000000012f508
 0.69% lte-softmodem.R lte-softmodem.Rel14 [.] idft1024
 0.67% lte-softmodem.R lte-softmodem.Rel14 [.] recv_IF4p5
 0.62% irq/311-enp1s0 [kernel.kallsyms] [k] pick_next_task_rt
 0.55% irq/311-enp1s0 [kernel.kallsyms] [k] rtl8169_poll
 0.54% ru_thread_FH 0 [kernel.kallsyms] [k] processcompl
 0.54% lte-softmodem.R [kernel.kallsyms] [k] mutex_spin_on_owner.isra.5
 0.54% ru_thread_FH 0 [kernel.kallsyms] [k] enqueue_hrtimer
 0.54% lte-softmodem.R [kernel.kallsyms] [k] select_task_rq_rt
 0.49% ru_thread_FH 0 lte-softmodem.Rel14 [.] send_IF4p5
 0.49% ru_thread_FH 0 lte-softmodem.Rel14 [.] dft64
 0.41% ru_thread_FH 0 [kernel.kallsyms] [k] cpupri_find
 0.41% swapper [kernel.kallsyms] [k] _find_next_bit.part.0
 0.41% ru_thread_FH 0 libc-2.23.so [.] inet_ntop
 0.41% irq/311-enp1s0 [kernel.kallsyms] [k] fib_validate_source
 0.41% lte-softmodem.R [kernel.kallsyms] [k] __skb_wait_for_more_packets
 0.41% irq/311-enp1s0 [kernel.kallsyms] [k] find_next_push_cpu
 0.37% ru_thread_FH 0 [kernel.kallsyms] [k] copy_user_enhanced_fast_str
 0.36% swapper [kernel.kallsyms] [k] refresh_cpu_vm_stats
 0.36% ru_thread_FH 0 [kernel.kallsyms] [k] __check_object_size
 0.36% lte-softmodem.R lte-softmodem.Rel14 [.] dft12288
 0.36% ru_thread_FH 0 [kernel.kallsyms] [k] proc_do_submiturb
 0.36% ru_thread_FH 0 [kernel.kallsyms] [k] usb_submit_urb.part.6
 0.36% ru_thread_FH 0 [kernel.kallsyms] [k] security_socket_sendmsg
 0.32% lte-softmodem.R lte-softmodem.Rel14 [.] dft1024
 0.32% ru_thread_FH 0 [kernel.kallsyms] [k] __fget
 0.32% swapper [kernel.kallsyms] [k] hrtimer_start_range_ns
 0.32% swapper [kernel.kallsyms] [k] __schedule
 0.32% ru_thread_FH 0 [kernel.kallsyms] [k] do_vfs_ioctl
 0.32% ru_thread_FH 0 [kernel.kallsyms] [k] csum_and_copy_from_iter
 0.32% ru_thread_FH 0 [kernel.kallsyms] [k] perf_event_task_tick
 0.32% irq/311-enp1s0 [kernel.kallsyms] [k] __build_skb
 0.32% ru_thread_FH 0 libuhd.so.003.010 [.] 0x0000000000209cb6


After: 



# Overhead Command Shared Object Symbol 
# ........ ............... .......................... .........................
#
 55.82% swapper [kernel.kallsyms] [k] cpu_startup_entry
 2.92% ru_thread_FH 0 liboai_usrpdevif.so [.] _ZL13trx_usrp_readP17
 2.34% mmcqd/0 [kernel.kallsyms] [k] sdhci_execute_tuning
 1.74% lte-softmodem.R lte-softmodem.Rel14 [.] idft64
 1.02% ru_thread_FH 0 [kernel.kallsyms] [k] copy_user_enhanced_fa
 1.02% lte-softmodem.R lte-softmodem.Rel14 [.] idft1024
 1.01% irq/311-enp1s0 [kernel.kallsyms] [k] __build_skb
 0.89% lte-softmodem.R [kernel.kallsyms] [k] SYSC_recvfrom
 0.84% swapper [kernel.kallsyms] [k] refresh_cpu_vm_stats
 0.81% ru_thread_FH 0 libpthread-2.23.so [.] pthread_cond_timedwai
 0.71% lte-softmodem.R lte-softmodem.Rel14 [.] dft256
 0.70% irq/311-enp1s0 [kernel.kallsyms] [k] fib_table_lookup
 0.70% ru_thread_FH 0 lte-softmodem.Rel14 [.] send_IF4p5
 0.61% ru_thread_FH 0 [kernel.kallsyms] [k] update_blocked_averag
 0.61% ru_thread_FH 0 libusb-1.0.so.0.1.0 [.] libusb_submit_transfe
 0.61% lte-softmodem.R [kernel.kallsyms] [k] pvclock_gtod_notify
 0.60% irq/311-enp1s0 [kernel.kallsyms] [k] rtl8169_poll
 0.57% swapper [kernel.kallsyms] [k] fold_diff
 0.55% swapper [kernel.kallsyms] [k] _find_next_bit.part.0
 0.55% ru_thread_FH 0 [kernel.kallsyms] [k] proc_do_submiturb
 0.54% ru_thread_FH 0 libpthread-2.23.so [.] pthread_mutex_lock
 0.54% lte-softmodem.R libusb-1.0.so.0.1.0 [.] 0x0000000000004200
 0.54% lte-softmodem.R libuhd.so.003.010 [.] _ZNK3uhd11time_spec_t
 0.52% ksoftirqd/3 [kernel.kallsyms] [k] update_blocked_averag
 0.52% ru_thread_FH 0 [kernel.kallsyms] [k] get_page_from_freelis
 0.49% lte-softmodem.R lte-softmodem.Rel14 [.] idft256
 0.47% ru_thread_FH 0 [kernel.kallsyms] [k] futex_wait_queue_me
 0.47% rcu_preempt [kernel.kallsyms] [k] update_blocked_averag
 0.47% lte-softmodem.R libpthread-2.23.so [.] __pthread_enable_asyn
 0.46% ru_thread_FH 0 [kernel.kallsyms] [k] cpupri_set
 0.46% irq/311-enp1s0 [kernel.kallsyms] [k] udp_v4_early_demux
 0.46% swapper [kernel.kallsyms] [k] __tick_nohz_idle_ente
 0.42% ru_thread_FH 0 [kernel.kallsyms] [k] mutex_spin_on_owner.i
 0.42% irq/311-enp1s0 [kernel.kallsyms] [k] rtl8169_interrupt
 0.41% irq/311-enp1s0 [kernel.kallsyms] [k] memcpy_erms
 0.37% ru_thread_FH 0 lte-softmodem.Rel14 [.] dft1024
 0.36% ru_thread_FH 0 [kernel.kallsyms] [k] __schedule
 0.36% swapper [kernel.kallsyms] [k] atomic_notifier_call_
 0.36% ru_thread_FH 0 [kernel.kallsyms] [k] sys_futex
 0.36% irq/311-enp1s0 [kernel.kallsyms] [k] napi_gro_receive
 0.36% ru_thread_FH 0 [kernel.kallsyms] [k] netif_skb_features
 0.36% ru_thread_FH 0 libc-2.23.so [.] __clock_gettime



ethernet delay




share|improve this question






















  • Try tracing/profiling your kernel so you could compare when it spends the most time. Do it when it works fine, secondly followed after latency degradation. Here is more info on doing tracing: brendangregg.com/perf.html. Basically, fire up perf record -F 99 -ag -- sleep 60 to take a system profile of one minute
    – KWubbufetowicz
    Nov 6 '17 at 15:43














up vote
0
down vote

favorite












I have an ubuntu 14.04, low-latency kernel, installed on an upboard machine. I'm using this machine for very low latency application (i.e. LTE). Briefly, this machine gets some packets on the Ethernet interface, which are retransmitted on a USRP radio interface through USB 3.0. Every thing goes fine, but after a certain time (close to 5:30 minutes), the delay significantly increases, which disturbs a lot the application.



I disabled all CPU power management, and CPUs frequency are on the maximum. I can't see if the frame RX time is increased on Ethernet, or in the contrary if the TX increases on USB 3.0. Nevertheless, this seems to be occurring at exactly the same time.



Edit:



I ran a perf on the kernel using: 



perf record -F 99 -a -- sleep 60


This is totally new for me, but it does not seem to be anything different between before/after the problem occurs. Here are the results:



Before: 



# Overhead Command Shared Object Symbol 
# ........ ............... ......................... ...............................
#
 61.47% swapper [kernel.kallsyms] [k] cpu_startup_entry
 2.28% lte-softmodem.R lte-softmodem.Rel14 [.] idft64
 1.89% lte-softmodem.R lte-softmodem.Rel14 [.] PHY_ofdm_mod
 1.21% ru_thread_FH 0 liboai_usrpdevif.so [.] _ZL13trx_usrp_readP17openai
 1.11% lte-softmodem.R [kernel.kallsyms] [k] copy_user_enhanced_fast_str
 0.90% lte-softmodem.R lte-softmodem.Rel14 [.] dft256
 0.76% lte-softmodem.R lte-softmodem.Rel14 [.] idft256
 0.73% ru_thread_FH 0 libpthread-2.23.so [.] pthread_mutex_unlock
 0.70% ru_thread_FH 0 [kernel.kallsyms] [k] pick_next_task_fair
 0.70% ru_thread_FH 0 libuhd.so.003.010 [.] 0x000000000012f508
 0.69% lte-softmodem.R lte-softmodem.Rel14 [.] idft1024
 0.67% lte-softmodem.R lte-softmodem.Rel14 [.] recv_IF4p5
 0.62% irq/311-enp1s0 [kernel.kallsyms] [k] pick_next_task_rt
 0.55% irq/311-enp1s0 [kernel.kallsyms] [k] rtl8169_poll
 0.54% ru_thread_FH 0 [kernel.kallsyms] [k] processcompl
 0.54% lte-softmodem.R [kernel.kallsyms] [k] mutex_spin_on_owner.isra.5
 0.54% ru_thread_FH 0 [kernel.kallsyms] [k] enqueue_hrtimer
 0.54% lte-softmodem.R [kernel.kallsyms] [k] select_task_rq_rt
 0.49% ru_thread_FH 0 lte-softmodem.Rel14 [.] send_IF4p5
 0.49% ru_thread_FH 0 lte-softmodem.Rel14 [.] dft64
 0.41% ru_thread_FH 0 [kernel.kallsyms] [k] cpupri_find
 0.41% swapper [kernel.kallsyms] [k] _find_next_bit.part.0
 0.41% ru_thread_FH 0 libc-2.23.so [.] inet_ntop
 0.41% irq/311-enp1s0 [kernel.kallsyms] [k] fib_validate_source
 0.41% lte-softmodem.R [kernel.kallsyms] [k] __skb_wait_for_more_packets
 0.41% irq/311-enp1s0 [kernel.kallsyms] [k] find_next_push_cpu
 0.37% ru_thread_FH 0 [kernel.kallsyms] [k] copy_user_enhanced_fast_str
 0.36% swapper [kernel.kallsyms] [k] refresh_cpu_vm_stats
 0.36% ru_thread_FH 0 [kernel.kallsyms] [k] __check_object_size
 0.36% lte-softmodem.R lte-softmodem.Rel14 [.] dft12288
 0.36% ru_thread_FH 0 [kernel.kallsyms] [k] proc_do_submiturb
 0.36% ru_thread_FH 0 [kernel.kallsyms] [k] usb_submit_urb.part.6
 0.36% ru_thread_FH 0 [kernel.kallsyms] [k] security_socket_sendmsg
 0.32% lte-softmodem.R lte-softmodem.Rel14 [.] dft1024
 0.32% ru_thread_FH 0 [kernel.kallsyms] [k] __fget
 0.32% swapper [kernel.kallsyms] [k] hrtimer_start_range_ns
 0.32% swapper [kernel.kallsyms] [k] __schedule
 0.32% ru_thread_FH 0 [kernel.kallsyms] [k] do_vfs_ioctl
 0.32% ru_thread_FH 0 [kernel.kallsyms] [k] csum_and_copy_from_iter
 0.32% ru_thread_FH 0 [kernel.kallsyms] [k] perf_event_task_tick
 0.32% irq/311-enp1s0 [kernel.kallsyms] [k] __build_skb
 0.32% ru_thread_FH 0 libuhd.so.003.010 [.] 0x0000000000209cb6


After: 



# Overhead Command Shared Object Symbol 
# ........ ............... .......................... .........................
#
 55.82% swapper [kernel.kallsyms] [k] cpu_startup_entry
 2.92% ru_thread_FH 0 liboai_usrpdevif.so [.] _ZL13trx_usrp_readP17
 2.34% mmcqd/0 [kernel.kallsyms] [k] sdhci_execute_tuning
 1.74% lte-softmodem.R lte-softmodem.Rel14 [.] idft64
 1.02% ru_thread_FH 0 [kernel.kallsyms] [k] copy_user_enhanced_fa
 1.02% lte-softmodem.R lte-softmodem.Rel14 [.] idft1024
 1.01% irq/311-enp1s0 [kernel.kallsyms] [k] __build_skb
 0.89% lte-softmodem.R [kernel.kallsyms] [k] SYSC_recvfrom
 0.84% swapper [kernel.kallsyms] [k] refresh_cpu_vm_stats
 0.81% ru_thread_FH 0 libpthread-2.23.so [.] pthread_cond_timedwai
 0.71% lte-softmodem.R lte-softmodem.Rel14 [.] dft256
 0.70% irq/311-enp1s0 [kernel.kallsyms] [k] fib_table_lookup
 0.70% ru_thread_FH 0 lte-softmodem.Rel14 [.] send_IF4p5
 0.61% ru_thread_FH 0 [kernel.kallsyms] [k] update_blocked_averag
 0.61% ru_thread_FH 0 libusb-1.0.so.0.1.0 [.] libusb_submit_transfe
 0.61% lte-softmodem.R [kernel.kallsyms] [k] pvclock_gtod_notify
 0.60% irq/311-enp1s0 [kernel.kallsyms] [k] rtl8169_poll
 0.57% swapper [kernel.kallsyms] [k] fold_diff
 0.55% swapper [kernel.kallsyms] [k] _find_next_bit.part.0
 0.55% ru_thread_FH 0 [kernel.kallsyms] [k] proc_do_submiturb
 0.54% ru_thread_FH 0 libpthread-2.23.so [.] pthread_mutex_lock
 0.54% lte-softmodem.R libusb-1.0.so.0.1.0 [.] 0x0000000000004200
 0.54% lte-softmodem.R libuhd.so.003.010 [.] _ZNK3uhd11time_spec_t
 0.52% ksoftirqd/3 [kernel.kallsyms] [k] update_blocked_averag
 0.52% ru_thread_FH 0 [kernel.kallsyms] [k] get_page_from_freelis
 0.49% lte-softmodem.R lte-softmodem.Rel14 [.] idft256
 0.47% ru_thread_FH 0 [kernel.kallsyms] [k] futex_wait_queue_me
 0.47% rcu_preempt [kernel.kallsyms] [k] update_blocked_averag
 0.47% lte-softmodem.R libpthread-2.23.so [.] __pthread_enable_asyn
 0.46% ru_thread_FH 0 [kernel.kallsyms] [k] cpupri_set
 0.46% irq/311-enp1s0 [kernel.kallsyms] [k] udp_v4_early_demux
 0.46% swapper [kernel.kallsyms] [k] __tick_nohz_idle_ente
 0.42% ru_thread_FH 0 [kernel.kallsyms] [k] mutex_spin_on_owner.i
 0.42% irq/311-enp1s0 [kernel.kallsyms] [k] rtl8169_interrupt
 0.41% irq/311-enp1s0 [kernel.kallsyms] [k] memcpy_erms
 0.37% ru_thread_FH 0 lte-softmodem.Rel14 [.] dft1024
 0.36% ru_thread_FH 0 [kernel.kallsyms] [k] __schedule
 0.36% swapper [kernel.kallsyms] [k] atomic_notifier_call_
 0.36% ru_thread_FH 0 [kernel.kallsyms] [k] sys_futex
 0.36% irq/311-enp1s0 [kernel.kallsyms] [k] napi_gro_receive
 0.36% ru_thread_FH 0 [kernel.kallsyms] [k] netif_skb_features
 0.36% ru_thread_FH 0 libc-2.23.so [.] __clock_gettime



ethernet delay




share|improve this question






















  • Try tracing/profiling your kernel so you could compare when it spends the most time. Do it when it works fine, secondly followed after latency degradation. Here is more info on doing tracing: brendangregg.com/perf.html. Basically, fire up perf record -F 99 -ag -- sleep 60 to take a system profile of one minute
    – KWubbufetowicz
    Nov 6 '17 at 15:43












up vote
0
down vote

favorite









up vote
0
down vote

favorite











I have an ubuntu 14.04, low-latency kernel, installed on an upboard machine. I'm using this machine for very low latency application (i.e. LTE). Briefly, this machine gets some packets on the Ethernet interface, which are retransmitted on a USRP radio interface through USB 3.0. Every thing goes fine, but after a certain time (close to 5:30 minutes), the delay significantly increases, which disturbs a lot the application.



I disabled all CPU power management, and CPUs frequency are on the maximum. I can't see if the frame RX time is increased on Ethernet, or in the contrary if the TX increases on USB 3.0. Nevertheless, this seems to be occurring at exactly the same time.



Edit:



I ran a perf on the kernel using: 



perf record -F 99 -a -- sleep 60


This is totally new for me, but it does not seem to be anything different between before/after the problem occurs. Here are the results:



Before: 



# Overhead Command Shared Object Symbol 
# ........ ............... ......................... ...............................
#
 61.47% swapper [kernel.kallsyms] [k] cpu_startup_entry
 2.28% lte-softmodem.R lte-softmodem.Rel14 [.] idft64
 1.89% lte-softmodem.R lte-softmodem.Rel14 [.] PHY_ofdm_mod
 1.21% ru_thread_FH 0 liboai_usrpdevif.so [.] _ZL13trx_usrp_readP17openai
 1.11% lte-softmodem.R [kernel.kallsyms] [k] copy_user_enhanced_fast_str
 0.90% lte-softmodem.R lte-softmodem.Rel14 [.] dft256
 0.76% lte-softmodem.R lte-softmodem.Rel14 [.] idft256
 0.73% ru_thread_FH 0 libpthread-2.23.so [.] pthread_mutex_unlock
 0.70% ru_thread_FH 0 [kernel.kallsyms] [k] pick_next_task_fair
 0.70% ru_thread_FH 0 libuhd.so.003.010 [.] 0x000000000012f508
 0.69% lte-softmodem.R lte-softmodem.Rel14 [.] idft1024
 0.67% lte-softmodem.R lte-softmodem.Rel14 [.] recv_IF4p5
 0.62% irq/311-enp1s0 [kernel.kallsyms] [k] pick_next_task_rt
 0.55% irq/311-enp1s0 [kernel.kallsyms] [k] rtl8169_poll
 0.54% ru_thread_FH 0 [kernel.kallsyms] [k] processcompl
 0.54% lte-softmodem.R [kernel.kallsyms] [k] mutex_spin_on_owner.isra.5
 0.54% ru_thread_FH 0 [kernel.kallsyms] [k] enqueue_hrtimer
 0.54% lte-softmodem.R [kernel.kallsyms] [k] select_task_rq_rt
 0.49% ru_thread_FH 0 lte-softmodem.Rel14 [.] send_IF4p5
 0.49% ru_thread_FH 0 lte-softmodem.Rel14 [.] dft64
 0.41% ru_thread_FH 0 [kernel.kallsyms] [k] cpupri_find
 0.41% swapper [kernel.kallsyms] [k] _find_next_bit.part.0
 0.41% ru_thread_FH 0 libc-2.23.so [.] inet_ntop
 0.41% irq/311-enp1s0 [kernel.kallsyms] [k] fib_validate_source
 0.41% lte-softmodem.R [kernel.kallsyms] [k] __skb_wait_for_more_packets
 0.41% irq/311-enp1s0 [kernel.kallsyms] [k] find_next_push_cpu
 0.37% ru_thread_FH 0 [kernel.kallsyms] [k] copy_user_enhanced_fast_str
 0.36% swapper [kernel.kallsyms] [k] refresh_cpu_vm_stats
 0.36% ru_thread_FH 0 [kernel.kallsyms] [k] __check_object_size
 0.36% lte-softmodem.R lte-softmodem.Rel14 [.] dft12288
 0.36% ru_thread_FH 0 [kernel.kallsyms] [k] proc_do_submiturb
 0.36% ru_thread_FH 0 [kernel.kallsyms] [k] usb_submit_urb.part.6
 0.36% ru_thread_FH 0 [kernel.kallsyms] [k] security_socket_sendmsg
 0.32% lte-softmodem.R lte-softmodem.Rel14 [.] dft1024
 0.32% ru_thread_FH 0 [kernel.kallsyms] [k] __fget
 0.32% swapper [kernel.kallsyms] [k] hrtimer_start_range_ns
 0.32% swapper [kernel.kallsyms] [k] __schedule
 0.32% ru_thread_FH 0 [kernel.kallsyms] [k] do_vfs_ioctl
 0.32% ru_thread_FH 0 [kernel.kallsyms] [k] csum_and_copy_from_iter
 0.32% ru_thread_FH 0 [kernel.kallsyms] [k] perf_event_task_tick
 0.32% irq/311-enp1s0 [kernel.kallsyms] [k] __build_skb
 0.32% ru_thread_FH 0 libuhd.so.003.010 [.] 0x0000000000209cb6


After: 



# Overhead Command Shared Object Symbol 
# ........ ............... .......................... .........................
#
 55.82% swapper [kernel.kallsyms] [k] cpu_startup_entry
 2.92% ru_thread_FH 0 liboai_usrpdevif.so [.] _ZL13trx_usrp_readP17
 2.34% mmcqd/0 [kernel.kallsyms] [k] sdhci_execute_tuning
 1.74% lte-softmodem.R lte-softmodem.Rel14 [.] idft64
 1.02% ru_thread_FH 0 [kernel.kallsyms] [k] copy_user_enhanced_fa
 1.02% lte-softmodem.R lte-softmodem.Rel14 [.] idft1024
 1.01% irq/311-enp1s0 [kernel.kallsyms] [k] __build_skb
 0.89% lte-softmodem.R [kernel.kallsyms] [k] SYSC_recvfrom
 0.84% swapper [kernel.kallsyms] [k] refresh_cpu_vm_stats
 0.81% ru_thread_FH 0 libpthread-2.23.so [.] pthread_cond_timedwai
 0.71% lte-softmodem.R lte-softmodem.Rel14 [.] dft256
 0.70% irq/311-enp1s0 [kernel.kallsyms] [k] fib_table_lookup
 0.70% ru_thread_FH 0 lte-softmodem.Rel14 [.] send_IF4p5
 0.61% ru_thread_FH 0 [kernel.kallsyms] [k] update_blocked_averag
 0.61% ru_thread_FH 0 libusb-1.0.so.0.1.0 [.] libusb_submit_transfe
 0.61% lte-softmodem.R [kernel.kallsyms] [k] pvclock_gtod_notify
 0.60% irq/311-enp1s0 [kernel.kallsyms] [k] rtl8169_poll
 0.57% swapper [kernel.kallsyms] [k] fold_diff
 0.55% swapper [kernel.kallsyms] [k] _find_next_bit.part.0
 0.55% ru_thread_FH 0 [kernel.kallsyms] [k] proc_do_submiturb
 0.54% ru_thread_FH 0 libpthread-2.23.so [.] pthread_mutex_lock
 0.54% lte-softmodem.R libusb-1.0.so.0.1.0 [.] 0x0000000000004200
 0.54% lte-softmodem.R libuhd.so.003.010 [.] _ZNK3uhd11time_spec_t
 0.52% ksoftirqd/3 [kernel.kallsyms] [k] update_blocked_averag
 0.52% ru_thread_FH 0 [kernel.kallsyms] [k] get_page_from_freelis
 0.49% lte-softmodem.R lte-softmodem.Rel14 [.] idft256
 0.47% ru_thread_FH 0 [kernel.kallsyms] [k] futex_wait_queue_me
 0.47% rcu_preempt [kernel.kallsyms] [k] update_blocked_averag
 0.47% lte-softmodem.R libpthread-2.23.so [.] __pthread_enable_asyn
 0.46% ru_thread_FH 0 [kernel.kallsyms] [k] cpupri_set
 0.46% irq/311-enp1s0 [kernel.kallsyms] [k] udp_v4_early_demux
 0.46% swapper [kernel.kallsyms] [k] __tick_nohz_idle_ente
 0.42% ru_thread_FH 0 [kernel.kallsyms] [k] mutex_spin_on_owner.i
 0.42% irq/311-enp1s0 [kernel.kallsyms] [k] rtl8169_interrupt
 0.41% irq/311-enp1s0 [kernel.kallsyms] [k] memcpy_erms
 0.37% ru_thread_FH 0 lte-softmodem.Rel14 [.] dft1024
 0.36% ru_thread_FH 0 [kernel.kallsyms] [k] __schedule
 0.36% swapper [kernel.kallsyms] [k] atomic_notifier_call_
 0.36% ru_thread_FH 0 [kernel.kallsyms] [k] sys_futex
 0.36% irq/311-enp1s0 [kernel.kallsyms] [k] napi_gro_receive
 0.36% ru_thread_FH 0 [kernel.kallsyms] [k] netif_skb_features
 0.36% ru_thread_FH 0 libc-2.23.so [.] __clock_gettime



ethernet delay




share|improve this question














I have an ubuntu 14.04, low-latency kernel, installed on an upboard machine. I'm using this machine for very low latency application (i.e. LTE). Briefly, this machine gets some packets on the Ethernet interface, which are retransmitted on a USRP radio interface through USB 3.0. Every thing goes fine, but after a certain time (close to 5:30 minutes), the delay significantly increases, which disturbs a lot the application.



I disabled all CPU power management, and CPUs frequency are on the maximum. I can't see if the frame RX time is increased on Ethernet, or in the contrary if the TX increases on USB 3.0. Nevertheless, this seems to be occurring at exactly the same time.



Edit:



I ran a perf on the kernel using: 



perf record -F 99 -a -- sleep 60


This is totally new for me, but it does not seem to be anything different between before/after the problem occurs. Here are the results:



Before: 



# Overhead Command Shared Object Symbol 
# ........ ............... ......................... ...............................
#
 61.47% swapper [kernel.kallsyms] [k] cpu_startup_entry
 2.28% lte-softmodem.R lte-softmodem.Rel14 [.] idft64
 1.89% lte-softmodem.R lte-softmodem.Rel14 [.] PHY_ofdm_mod
 1.21% ru_thread_FH 0 liboai_usrpdevif.so [.] _ZL13trx_usrp_readP17openai
 1.11% lte-softmodem.R [kernel.kallsyms] [k] copy_user_enhanced_fast_str
 0.90% lte-softmodem.R lte-softmodem.Rel14 [.] dft256
 0.76% lte-softmodem.R lte-softmodem.Rel14 [.] idft256
 0.73% ru_thread_FH 0 libpthread-2.23.so [.] pthread_mutex_unlock
 0.70% ru_thread_FH 0 [kernel.kallsyms] [k] pick_next_task_fair
 0.70% ru_thread_FH 0 libuhd.so.003.010 [.] 0x000000000012f508
 0.69% lte-softmodem.R lte-softmodem.Rel14 [.] idft1024
 0.67% lte-softmodem.R lte-softmodem.Rel14 [.] recv_IF4p5
 0.62% irq/311-enp1s0 [kernel.kallsyms] [k] pick_next_task_rt
 0.55% irq/311-enp1s0 [kernel.kallsyms] [k] rtl8169_poll
 0.54% ru_thread_FH 0 [kernel.kallsyms] [k] processcompl
 0.54% lte-softmodem.R [kernel.kallsyms] [k] mutex_spin_on_owner.isra.5
 0.54% ru_thread_FH 0 [kernel.kallsyms] [k] enqueue_hrtimer
 0.54% lte-softmodem.R [kernel.kallsyms] [k] select_task_rq_rt
 0.49% ru_thread_FH 0 lte-softmodem.Rel14 [.] send_IF4p5
 0.49% ru_thread_FH 0 lte-softmodem.Rel14 [.] dft64
 0.41% ru_thread_FH 0 [kernel.kallsyms] [k] cpupri_find
 0.41% swapper [kernel.kallsyms] [k] _find_next_bit.part.0
 0.41% ru_thread_FH 0 libc-2.23.so [.] inet_ntop
 0.41% irq/311-enp1s0 [kernel.kallsyms] [k] fib_validate_source
 0.41% lte-softmodem.R [kernel.kallsyms] [k] __skb_wait_for_more_packets
 0.41% irq/311-enp1s0 [kernel.kallsyms] [k] find_next_push_cpu
 0.37% ru_thread_FH 0 [kernel.kallsyms] [k] copy_user_enhanced_fast_str
 0.36% swapper [kernel.kallsyms] [k] refresh_cpu_vm_stats
 0.36% ru_thread_FH 0 [kernel.kallsyms] [k] __check_object_size
 0.36% lte-softmodem.R lte-softmodem.Rel14 [.] dft12288
 0.36% ru_thread_FH 0 [kernel.kallsyms] [k] proc_do_submiturb
 0.36% ru_thread_FH 0 [kernel.kallsyms] [k] usb_submit_urb.part.6
 0.36% ru_thread_FH 0 [kernel.kallsyms] [k] security_socket_sendmsg
 0.32% lte-softmodem.R lte-softmodem.Rel14 [.] dft1024
 0.32% ru_thread_FH 0 [kernel.kallsyms] [k] __fget
 0.32% swapper [kernel.kallsyms] [k] hrtimer_start_range_ns
 0.32% swapper [kernel.kallsyms] [k] __schedule
 0.32% ru_thread_FH 0 [kernel.kallsyms] [k] do_vfs_ioctl
 0.32% ru_thread_FH 0 [kernel.kallsyms] [k] csum_and_copy_from_iter
 0.32% ru_thread_FH 0 [kernel.kallsyms] [k] perf_event_task_tick
 0.32% irq/311-enp1s0 [kernel.kallsyms] [k] __build_skb
 0.32% ru_thread_FH 0 libuhd.so.003.010 [.] 0x0000000000209cb6


After: 



# Overhead Command Shared Object Symbol 
# ........ ............... .......................... .........................
#
 55.82% swapper [kernel.kallsyms] [k] cpu_startup_entry
 2.92% ru_thread_FH 0 liboai_usrpdevif.so [.] _ZL13trx_usrp_readP17
 2.34% mmcqd/0 [kernel.kallsyms] [k] sdhci_execute_tuning
 1.74% lte-softmodem.R lte-softmodem.Rel14 [.] idft64
 1.02% ru_thread_FH 0 [kernel.kallsyms] [k] copy_user_enhanced_fa
 1.02% lte-softmodem.R lte-softmodem.Rel14 [.] idft1024
 1.01% irq/311-enp1s0 [kernel.kallsyms] [k] __build_skb
 0.89% lte-softmodem.R [kernel.kallsyms] [k] SYSC_recvfrom
 0.84% swapper [kernel.kallsyms] [k] refresh_cpu_vm_stats
 0.81% ru_thread_FH 0 libpthread-2.23.so [.] pthread_cond_timedwai
 0.71% lte-softmodem.R lte-softmodem.Rel14 [.] dft256
 0.70% irq/311-enp1s0 [kernel.kallsyms] [k] fib_table_lookup
 0.70% ru_thread_FH 0 lte-softmodem.Rel14 [.] send_IF4p5
 0.61% ru_thread_FH 0 [kernel.kallsyms] [k] update_blocked_averag
 0.61% ru_thread_FH 0 libusb-1.0.so.0.1.0 [.] libusb_submit_transfe
 0.61% lte-softmodem.R [kernel.kallsyms] [k] pvclock_gtod_notify
 0.60% irq/311-enp1s0 [kernel.kallsyms] [k] rtl8169_poll
 0.57% swapper [kernel.kallsyms] [k] fold_diff
 0.55% swapper [kernel.kallsyms] [k] _find_next_bit.part.0
 0.55% ru_thread_FH 0 [kernel.kallsyms] [k] proc_do_submiturb
 0.54% ru_thread_FH 0 libpthread-2.23.so [.] pthread_mutex_lock
 0.54% lte-softmodem.R libusb-1.0.so.0.1.0 [.] 0x0000000000004200
 0.54% lte-softmodem.R libuhd.so.003.010 [.] _ZNK3uhd11time_spec_t
 0.52% ksoftirqd/3 [kernel.kallsyms] [k] update_blocked_averag
 0.52% ru_thread_FH 0 [kernel.kallsyms] [k] get_page_from_freelis
 0.49% lte-softmodem.R lte-softmodem.Rel14 [.] idft256
 0.47% ru_thread_FH 0 [kernel.kallsyms] [k] futex_wait_queue_me
 0.47% rcu_preempt [kernel.kallsyms] [k] update_blocked_averag
 0.47% lte-softmodem.R libpthread-2.23.so [.] __pthread_enable_asyn
 0.46% ru_thread_FH 0 [kernel.kallsyms] [k] cpupri_set
 0.46% irq/311-enp1s0 [kernel.kallsyms] [k] udp_v4_early_demux
 0.46% swapper [kernel.kallsyms] [k] __tick_nohz_idle_ente
 0.42% ru_thread_FH 0 [kernel.kallsyms] [k] mutex_spin_on_owner.i
 0.42% irq/311-enp1s0 [kernel.kallsyms] [k] rtl8169_interrupt
 0.41% irq/311-enp1s0 [kernel.kallsyms] [k] memcpy_erms
 0.37% ru_thread_FH 0 lte-softmodem.Rel14 [.] dft1024
 0.36% ru_thread_FH 0 [kernel.kallsyms] [k] __schedule
 0.36% swapper [kernel.kallsyms] [k] atomic_notifier_call_
 0.36% ru_thread_FH 0 [kernel.kallsyms] [k] sys_futex
 0.36% irq/311-enp1s0 [kernel.kallsyms] [k] napi_gro_receive
 0.36% ru_thread_FH 0 [kernel.kallsyms] [k] netif_skb_features
 0.36% ru_thread_FH 0 libc-2.23.so [.] __clock_gettime




ethernet delay





share|improve this question













share|improve this question




share|improve this question








edited Nov 8 '17 at 14:57

























asked Nov 6 '17 at 15:35









Spider

11




11











  • Try tracing/profiling your kernel so you could compare when it spends the most time. Do it when it works fine, secondly followed after latency degradation. Here is more info on doing tracing: brendangregg.com/perf.html. Basically, fire up perf record -F 99 -ag -- sleep 60 to take a system profile of one minute
    – KWubbufetowicz
    Nov 6 '17 at 15:43
















  • Try tracing/profiling your kernel so you could compare when it spends the most time. Do it when it works fine, secondly followed after latency degradation. Here is more info on doing tracing: brendangregg.com/perf.html. Basically, fire up perf record -F 99 -ag -- sleep 60 to take a system profile of one minute
    – KWubbufetowicz
    Nov 6 '17 at 15:43















Try tracing/profiling your kernel so you could compare when it spends the most time. Do it when it works fine, secondly followed after latency degradation. Here is more info on doing tracing: brendangregg.com/perf.html. Basically, fire up perf record -F 99 -ag -- sleep 60 to take a system profile of one minute
– KWubbufetowicz
Nov 6 '17 at 15:43




Try tracing/profiling your kernel so you could compare when it spends the most time. Do it when it works fine, secondly followed after latency degradation. Here is more info on doing tracing: brendangregg.com/perf.html. Basically, fire up perf record -F 99 -ag -- sleep 60 to take a system profile of one minute
– KWubbufetowicz
Nov 6 '17 at 15:43















active

oldest

votes











Your Answer







StackExchange.ready(function()
var channelOptions =
tags: "".split(" "),
id: "106"
;
initTagRenderer("".split(" "), "".split(" "), channelOptions);

StackExchange.using("externalEditor", function()
// Have to fire editor after snippets, if snippets enabled
if (StackExchange.settings.snippets.snippetsEnabled)
StackExchange.using("snippets", function()
createEditor();
);

else
createEditor();

);

function createEditor()
StackExchange.prepareEditor(
heartbeatType: 'answer',
convertImagesToLinks: false,
noModals: false,
showLowRepImageUploadWarning: true,
reputationToPostImages: null,
bindNavPrevention: true,
postfix: "",
onDemand: true,
discardSelector: ".discard-answer"
,immediatelyShowMarkdownHelp:true
);



);













 

draft saved


draft discarded


















StackExchange.ready(
function ()
StackExchange.openid.initPostLogin('.new-post-login', 'https%3a%2f%2funix.stackexchange.com%2fquestions%2f402851%2fnetwork-latency-increase-after-a-certain-time%23new-answer', 'question_page');

);

Post as a guest






















active

oldest

votes













active

oldest

votes









active

oldest

votes






active

oldest

votes















 

draft saved


draft discarded















































 


draft saved


draft discarded














StackExchange.ready(
function ()
StackExchange.openid.initPostLogin('.new-post-login', 'https%3a%2f%2funix.stackexchange.com%2fquestions%2f402851%2fnetwork-latency-increase-after-a-certain-time%23new-answer', 'question_page');

);

Post as a guest
































































-

Popular posts from this blog

Peggy Mitchell

Image
EastEnders character This article is about the soap opera character. For the British tennis player, see Peggy Michell. For the author, see Margaret Mitchell. Peggy Mitchell Barbara Windsor as Peggy Mitchell (2008) EastEnders character Portrayed by Jo Warne (1991) Barbara Windsor (1994–2016) Duration 1991, 1994–2010, 2013–2016 First appearance Episode 650 30 April 1991  ( 1991-04-30 ) Last appearance Episode 5286 17 May 2016  ( 2016-05-17 ) (appearance) Episode 5287 19 May 2016 (voiceover) Introduced by Michael Ferguson (1991) Barbara Emile (1994) Louise Berridge (2004) Kate Harwood (2005) Lorraine Newman (2013) Dominic Treadwell-Collins (2014) Spin-off appearances The Mitchells - Naked Truths (1998) Classification Former; regular Profile Other names Peggy Butcher Occupation Barmaid Businesswoman Pub landlady Jo Warne as Peggy Mitchell (1991) Family Family Mitchell Father Jack Martin Mother Lily Martin Sisters Aunt ...
Read more

Palaiologos

Image
Palaiologos Παλαιολόγος Palaeologus, Palaeologue Imperial Family Double-headed eagle with the family cypher Country Byzantine Empire, Duchy of Montferrat (remaining lineage after Empire annexed by Ottomans) Founded 11th century  ( 11th century ) Founder Nikephoros Palaiologos (first known) Final ruler Constantine XI Palaiologos (Byzantine Empire) Margaret Paleologa (Montferrat) Titles Byzantine Emperor Marquess of Montferrat Style(s) "Augustus" "Basileus" "Autokrator" Traditions Greek Orthodoxy (predominantly) Roman Catholicism (remaining lineage in Montferrat) Dissolution 1533  ( 1533 ) Cadet branches Claimants: House of Kastrioti (defunct) House of Rurik (defunct) Palaiologan dynasty Chronology Michael VIII 1259–1282 with Andronikos II as co-emperor, 1261–1282 Andronikos II 1282–1328 with Michael IX (1294–1320) and Andronikos III (1321–1328) as co-emperors Andronikos III 1328–1341 John...
Read more

The Forum (Inglewood, California)

Image
The Forum "LA Forum" Prairie Ave. façade of The Forum in 2014 Full name The Forum, presented by Chase Former names The Forum (1967–1988) Great Western Forum (1988–2003) Address 3900 W. Manchester Blvd Location Inglewood, California Coordinates Coordinates: 33°57′29″N 118°20′31″W  /  33.95806°N 118.34194°W  / 33.95806; -118.34194 Public transit     Downtown Inglewood station Owner The Madison Square Garden Company Operator MSG Entertainment Seating type Reserved Capacity 17,500 Half-bowl: 8,000 Construction Broke ground July 1, 1966  ( 1966-07-01 ) Opened December 30, 1967  ( 1967-12-30 ) Renovated 1988, 2012–2014 Construction cost $16 million Renovation: 2014: $76.5 million Architect Charles Luckman Associates (original) Brisbin Brook Beynon (renovation) Structural engineer Johnson & Nielsen Associates (original) Severud Associates (renovation) Genera...
Read more