From mboxrd@z Thu Jan 1 00:00:00 1970 From: chensong Subject: hith latency when cpu is fully loaded Message-ID: <5DD33EDF.5040506@kylinos.cn>+334782671EFB64A8 Date: Tue, 19 Nov 2019 09:01:19 +0800 MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8; format=flowed Content-Transfer-Encoding: 7bit List-Id: Discussions about the Xenomai project List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , To: xenomai@xenomai.org Dear experts, i'm new in xenomai, i got an issue, here is the detail: Main processor architect: ARM64 phytium ft2000ahk Kernel release number: 4.14.4 cmdline:BOOT_IMAGE=/Image-tmp root=UUID=9fea0634-a9c9-4e9f-906c-9c36b7249822 console=ttyS1,115200 earlyprintk=uart8250-32bit,0x28001000 rw rootdelay=10 KEYBOARDTYPE=pc KEYTABLE=us security= xenomai release number:3.1-devel xenomai configuration: kylin@kylin-os:~/workspace/code/nudt-hgj-xenomai-tjrd$ grep configure config.status # Generated by configure. # Compiler output produced by configure, useful for debugging # configure, is in config.log if it exists. configured by ./configure, generated by GNU Autoconf 2.69, ac_configure_extra_args= ac_configure_extra_args="$ac_configure_extra_args --silent" set X /bin/bash './configure' '--with-core=cobalt' '--enable-smp' '--enable-pshared' $ac_configure_extra_args --no-create --no-recursion configure_time_dlsearch_path='/lib /usr/lib /lib/aarch64-linux-gnu /usr/lib/aarch64-linux-gnu /usr/lib/aarch64-linux-gnu/mesa-egl /usr/lib/aarch64-linux-gnu/mesa /usr/local/lib ' configure_time_lt_sys_library_path='' for var in reload_cmds old_postinstall_cmds old_postuninstall_cmds old_archive_cmds extract_expsyms_cmds old_archive_from_new_cmds old_archive_from_expsyms_cmds archive_cmds archive_expsym_cmds module_cmds module_expsym_cmds export_symbols_cmds prelink_cmds postlink_cmds postinstall_cmds postuninstall_cmds finish_cmds sys_lib_search_path_spec configure_time_dlsearch_path configure_time_lt_sys_library_path; do # on some systems where configure will not decide to define it. # Let's still pretend it is `configure' which instantiates (i.e., don't configure_input='Generated from '` `' by configure.' configure_input="$ac_file. $configure_input" case $configure_input in #( ac_sed_conf_input=`$as_echo "$configure_input" | *) ac_sed_conf_input=$configure_input;; s|@configure_input@|$ac_sed_conf_input|;t t $as_echo "/* $configure_input */" \ $as_echo "/* $configure_input */" \ # Libtool was configured on host `(hostname || uname -n) 2>/dev/null | sed 1q`: : \${LT_SYS_LIBRARY_PATH="$configure_time_lt_sys_library_path"} sys_lib_dlsearch_path_spec=$lt_configure_time_dlsearch_path # Explicit LT_SYS_LIBRARY_PATH set during ./configure time. configure_time_lt_sys_library_path=$lt_configure_time_lt_sys_library_path OR: kylin@kylin-os:~$ xeno-config --info Xenomai version: Xenomai/cobalt v3.1-devel -- # () Linux kylin-os 4.14.4.kylin.rt-1118-ipipe-trace+ #2 SMP PREEMPT Mon Nov 18 18:28:17 CST 2019 aarch64 aarch64 aarch64 GNU/Linux Kernel parameters: BOOT_IMAGE=/Image-tmp root=UUID=9fea0634-a9c9-4e9f-906c-9c36b7249822 console=ttyS1,115200 earlyprintk=uart8250-32bit,0x28001000 rw rootdelay=10 KEYBOARDTYPE=pc KEYTABLE=us security= I-pipe release #2 detected Cobalt core 3.1-devel detected Compiler: gcc version 5.4.0 20160609 (Ubuntu/Linaro 5.4.0-6kord1~16.04.10) Build args: --prefix=/usr --includedir=/usr/include/xenomai --mandir=/usr/share/man --with-testdir=/usr/lib/xenomai/testsuite --enable-smp --build aarch64-linux-gnu build_alias=aarch64-linux-gnu Desktop: kylin 4.0.2 (ubuntu likely desktop) Issue description: latency and cyclictest work fine in my system in most of cases, the worst latency is around 100us ~ 200us. however, when i ran a script to increase the cpu load in the system, the worst latency reached 2000us ~ 5000us or even worse. Basically, the script forks 6 processes by default and each process applies a four-pages buffer and keeps writing without any breath, no warning or error messages in dmesg. below is the script: #include #include #include #include #include #include #define PAGE_SIZE 4096 #define TEST_THREADS 6 unsigned int test_threads; void do_thread_test(void) { void *mm; char i = 0; printf("mem test thread start \n"); mm = malloc(PAGE_SIZE * 4); // 1M while(1) { for (i = 0; i<100; i++) memset(mm, i, PAGE_SIZE * 4); } } void thread_test(void) { pid_t pid[TEST_THREADS]; int i = 0; printf("begin start\n"); for (i = 0; i< test_threads; i++) { pid[i] = fork(); if (pid[i] == 0) do_thread_test(); } } int get_cpu_idle_info(int *idle, int *total) { FILE *fp; int var[5][7]; char name[5][20]; char *line; ssize_t read, len = 0; int i = 0; if ((fp = fopen("/proc/stat", "r")) == NULL) { printf("open /proc/stat err !\n"); return -1; } while((read = getline(&line, &len, fp)) != -1) { // fgets(buff, sizeof(buff), fp); sscanf(line, "%s %u %u %u %u %u %u %u", &name[i][0], &var[i][0], &var[i][1], &var[i][2], &var[i][3], &var[i][4], &var[i][5], &var[i][6]); i++; if (i >= 5) break; } fclose(fp); *idle = var[0][3]; *total = var[0][0] + var[0][1] + var[0][2] + var[0][3] + var[0][4] + var[0][5] + var[0][6]; // printf("%d %d %d %d %d %d %d total %d\n", var[0][0], var[0][1], var[0][2], var[0][3], var[0][4], var[0][5], var[0][6], *total); return 0; } int get_cpu_freq(void) { FILE *fp; char *line; ssize_t read, len = 0; int val = 0; if ((fp = fopen("/sys/devices/system/cpu/cpufreq/policy0/cpuinfo_cur_freq", "r")) == NULL) { printf("open /proc/stat err !\n"); return -1; } read = getline(&line, &len, fp); sscanf(line, "%d", &val); fclose(fp); return val; } int cal_cpu_loadavg(void) { int cpu_info[2][2]; int load = 0; if (get_cpu_idle_info(&cpu_info[0][0], &cpu_info[0][1]) != 0) return -1; sleep(1); if(get_cpu_idle_info(&cpu_info[1][0], &cpu_info[1][1]) != 0) return -1; load = ((cpu_info[1][0] - cpu_info[0][0]) * 100) / (cpu_info[1][1] - cpu_info[0][1]); return load; } int main(int argc, char **argv) { pid_t pid; int loadavg = 0; if (argc == 2) test_threads = atoi(argv[1]); else test_threads = TEST_THREADS; pid = fork(); if (pid == 0) { thread_test(); } else { while (1) { loadavg = cal_cpu_loadavg(); sleep(2); if (loadavg == -1) continue; else printf("load avg %d\n",100 - loadavg); } } } I enabled ipipe tracer and got the frozen like this: I-pipe frozen back-tracing service on 4.14.4.kylin.rt-1118-ipipe-trace+/ipipe release #2 ------------------------------------------------------------ CPU: 0, Freeze: 31865107520 cycles, Trace Points: 100 (+10) Calibrated minimum trace-point overhead: 0.568 us +----- Hard IRQs ('|': locked) |+-- Xenomai ||+- Linux ('*': domain stalled, '+': current, '#': current+stalled) ||| +---------- Delay flag ('+': > 1 us, '!': > 10 us) ||| | +- NMI noise ('N') ||| | | Type User Val. Time Delay Function (Parent) :|# func -2556! 162.196 ___xnlock_put+0x14 (__put_fd+0x17c) :|# func -2394 0.980 __ipipe_restore_head+0x20 (__put_fd+0x164) :|+ end 0x80000000 -2393+ 1.137 __ipipe_restore_head+0x94 (<00000000>) :|+ func -2391 1.000 gic_handle_irq+0x28 (el1_irq+0xc0) :|+ func -2390 0.862 irq_find_mapping+0x1c (gic_handle_irq+0x6c) :|+ func -2390 1.000 __ipipe_grab_irq+0x24 (gic_handle_irq+0x74) :|+ begin 0x00000004 -2389 0.941 __ipipe_grab_irq+0x44 (<00000000>) :|+ func -2388 0.843 __ipipe_dispatch_irq+0x20 (__ipipe_grab_irq+0x64) :|+ func -2387 0.862 irq_to_desc+0x14 (__ipipe_dispatch_irq+0xd4) :|+ func -2386 0.882 irq_to_desc+0x14 (__ipipe_dispatch_irq+0xe0) :|+ func -2385 0.980 __ipipe_ack_hrtimer_irq+0x1c (__ipipe_dispatch_irq+0x74) :|+ func -2384 0.823 __ipipe_ack_fasteoi_irq+0x14 (__ipipe_ack_hrtimer_irq+0x3c) :|+ func -2383 0.882 gic_hold_irq+0x14 (__ipipe_ack_fasteoi_irq+0x24) :|+ func -2382 0.941 arch_itimer_ack_phys+0xc (__ipipe_ack_hrtimer_irq+0x48) :|+ func -2381 0.823 __ipipe_end_fasteoi_irq+0x14 (__ipipe_ack_hrtimer_irq+0x54) :|+ func -2381 1.000 gic_release_irq+0x14 (__ipipe_end_fasteoi_irq+0x28) :|+ func -2380+ 1.156 dispatch_irq_head+0x28 (__ipipe_dispatch_irq+0x168) :|# func -2378! 154.705 xnintr_core_clock_handler+0x28 (dispatch_irq_head+0xb8) :|# func -2224 0.901 ___xnlock_get+0x14 (xnintr_core_clock_handler+0x120) :|# func -2223 0.901 xnclock_tick+0x24 (xnintr_core_clock_handler+0x12c) :|# func -2222 0.823 timerfd_handler+0x14 (xnclock_tick+0x108) :|# func -2221+ 1.019 xnsynch_wakeup_one_sleeper+0x1c (timerfd_handler+0x40) :|# func -2220+ 1.098 ___xnlock_get+0x14 (xnsynch_wakeup_one_sleeper+0x54) :|# func -2219 0.941 xnclock_core_ns_to_ticks+0x14 (xnclock_tick+0x18c) :|# func -2218 0.882 xnclock_core_local_shot+0x14 (xnclock_tick+0x264) :|# event tick@-1727 -2217 0.823 xnclock_core_local_shot+0x94 (<00000000>) :|# func -2216 0.980 ipipe_timer_set+0x1c (xnclock_core_local_shot+0x98) :|# func -2215 0.921 arch_timer_set_next_event_phys+0x18 (ipipe_timer_set+0x78) :|# func -2214! 156.666 ___xnlock_put+0x14 (xnintr_core_clock_handler+0x134) :|+ end 0x00000004 -2058 0.901 __ipipe_grab_irq+0x70 (<00000000>) :|+ func -2057 0.921 __ipipe_exit_irq+0x14 (__ipipe_grab_irq+0x74) :|+ func -2056! 331.666 __ipipe_check_root_interruptible+0x18 (el1_irq+0xe4) :|+ func -1724 0.980 gic_handle_irq+0x28 (el0_irq_naked+0x54) :|+ func -1723 0.862 irq_find_mapping+0x1c (gic_handle_irq+0x6c) :|+ func -1722 0.980 __ipipe_grab_irq+0x24 (gic_handle_irq+0x74) :|+ begin 0x00000004 -1721 0.901 __ipipe_grab_irq+0x44 (<00000000>) :|+ func -1721 0.823 __ipipe_dispatch_irq+0x20 (__ipipe_grab_irq+0x64) :|+ func -1720 0.843 irq_to_desc+0x14 (__ipipe_dispatch_irq+0xd4) :|+ func -1719 0.862 irq_to_desc+0x14 (__ipipe_dispatch_irq+0xe0) :|+ func -1718 0.960 __ipipe_ack_hrtimer_irq+0x1c (__ipipe_dispatch_irq+0x74) :|+ func -1717 0.843 __ipipe_ack_fasteoi_irq+0x14 (__ipipe_ack_hrtimer_irq+0x3c) :|+ func -1716 0.862 gic_hold_irq+0x14 (__ipipe_ack_fasteoi_irq+0x24) :|+ func -1715 0.921 arch_itimer_ack_phys+0xc (__ipipe_ack_hrtimer_irq+0x48) :|+ func -1714 0.823 __ipipe_end_fasteoi_irq+0x14 (__ipipe_ack_hrtimer_irq+0x54) :|+ func -1714 1.000 gic_release_irq+0x14 (__ipipe_end_fasteoi_irq+0x28) :|+ func -1713+ 1.156 dispatch_irq_head+0x28 (__ipipe_dispatch_irq+0x168) :|# func -1711+ 1.058 xnintr_core_clock_handler+0x28 (dispatch_irq_head+0xb8) :|# func -1710 0.921 ___xnlock_get+0x14 (xnintr_core_clock_handler+0x120) :|# func -1709 0.901 xnclock_tick+0x24 (xnintr_core_clock_handler+0x12c) :|# func -1709 0.823 timerfd_handler+0x14 (xnclock_tick+0x108) :|# func -1708+ 1.019 xnsynch_wakeup_one_sleeper+0x1c (timerfd_handler+0x40) :|# func -1707+ 1.098 ___xnlock_get+0x14 (xnsynch_wakeup_one_sleeper+0x54) :|# func -1706 0.941 xnclock_core_ns_to_ticks+0x14 (xnclock_tick+0x18c) :|# func -1705 0.882 xnclock_core_local_shot+0x14 (xnclock_tick+0x264) :|# event tick@-747 -1704 0.823 xnclock_core_local_shot+0x94 (<00000000>) :|# func -1703 0.960 ipipe_timer_set+0x1c (xnclock_core_local_shot+0x98) :|# func -1702 0.941 arch_timer_set_next_event_phys+0x18 (ipipe_timer_set+0x78) :|# func -1701+ 1.372 ___xnlock_put+0x14 (xnintr_core_clock_handler+0x134) :|+ end 0x00000004 -1700 0.823 __ipipe_grab_irq+0x70 (<00000000>) :|+ func -1699 0.960 __ipipe_exit_irq+0x14 (__ipipe_grab_irq+0x74) :|+ func -1698! 954.058 __ipipe_check_root_interruptible+0x18 (el0_irq_naked+0x78) :|+ func -744 0.960 gic_handle_irq+0x28 (el0_irq_naked+0x54) :|+ func -743 0.862 irq_find_mapping+0x1c (gic_handle_irq+0x6c) :|+ func -742 0.941 __ipipe_grab_irq+0x24 (gic_handle_irq+0x74) :|+ begin 0x00000004 -741 0.901 __ipipe_grab_irq+0x44 (<00000000>) :|+ func -740 0.862 __ipipe_dispatch_irq+0x20 (__ipipe_grab_irq+0x64) :|+ func -739 0.843 irq_to_desc+0x14 (__ipipe_dispatch_irq+0xd4) :|+ func -738 0.882 irq_to_desc+0x14 (__ipipe_dispatch_irq+0xe0) :|+ func -738 0.960 __ipipe_ack_hrtimer_irq+0x1c (__ipipe_dispatch_irq+0x74) :|+ func -737 0.843 __ipipe_ack_fasteoi_irq+0x14 (__ipipe_ack_hrtimer_irq+0x3c) :|+ func -736 0.862 gic_hold_irq+0x14 (__ipipe_ack_fasteoi_irq+0x24) :|+ func -735 0.921 arch_itimer_ack_phys+0xc (__ipipe_ack_hrtimer_irq+0x48) :|+ func -734 0.823 __ipipe_end_fasteoi_irq+0x14 (__ipipe_ack_hrtimer_irq+0x54) :|+ func -733 0.980 gic_release_irq+0x14 (__ipipe_end_fasteoi_irq+0x28) :|+ func -732+ 1.156 dispatch_irq_head+0x28 (__ipipe_dispatch_irq+0x168) :|# func -731+ 1.039 xnintr_core_clock_handler+0x28 (dispatch_irq_head+0xb8) :|# func -730 0.901 ___xnlock_get+0x14 (xnintr_core_clock_handler+0x120) :|# func -729 0.901 xnclock_tick+0x24 (xnintr_core_clock_handler+0x12c) :|# func -728 0.823 timerfd_handler+0x14 (xnclock_tick+0x108) :|# func -727+ 1.019 xnsynch_wakeup_one_sleeper+0x1c (timerfd_handler+0x40) :|# func -726+ 1.078 ___xnlock_get+0x14 (xnsynch_wakeup_one_sleeper+0x54) :|# func -725 0.921 xnclock_core_ns_to_ticks+0x14 (xnclock_tick+0x18c) :|# func -724 0.882 xnclock_core_local_shot+0x14 (xnclock_tick+0x264) :|# event tick@233 -723 0.823 xnclock_core_local_shot+0x94 (<00000000>) :|# func -723 0.980 ipipe_timer_set+0x1c (xnclock_core_local_shot+0x98) :|# func -722 0.921 arch_timer_set_next_event_phys+0x18 (ipipe_timer_set+0x78) :|# func -721+ 1.313 ___xnlock_put+0x14 (xnintr_core_clock_handler+0x134) :|+ end 0x00000004 -719 0.862 __ipipe_grab_irq+0x70 (<00000000>) :|+ func -719 0.960 __ipipe_exit_irq+0x14 (__ipipe_grab_irq+0x74) :|+ func -718! 301.392 __ipipe_check_root_interruptible+0x18 (el0_irq_naked+0x78) : + func -416 0.823 ipipe_fastcall_hook+0x14 (el0_svc_naked+0x20) : + func -415! 162.980 handle_head_syscall+0x24 (ipipe_fastcall_hook+0x24) : + func -252! 164.117 CoBaLt_trace+0x24 (handle_head_syscall+0x118) : + func -88 0.823 ipipe_trace_frozen_reset+0x2c (CoBaLt_trace+0x168) : + func -87! 82.411 __ipipe_global_path_lock+0xc (ipipe_trace_frozen_reset+0x34) : + func -5 0.882 __ipipe_spin_lock_irqsave+0x14 (__ipipe_global_path_lock+0x1c) :|+ begin 0x80000001 -4+ 2.607 __ipipe_spin_lock_irqsave+0xac (<00000000>) :|# func -2+ 1.098 __ipipe_spin_unlock_irqcomplete+0x18 (__ipipe_global_path_unlock+0x98) :|+ end 0x80000001 0 0.941 __ipipe_spin_unlock_irqcomplete+0x30 (<00000000>) < + freeze 0x007a7920 0 1.411 CoBaLt_trace+0x178 (<00000000>) + func 1 0.901 ipipe_fastcall_hook+0x14 (el0_svc_naked+0x20) + func 2 0.921 handle_head_syscall+0x24 (ipipe_fastcall_hook+0x24) + func 3 0.862 CoBaLt_read+0x20 (handle_head_syscall+0x118) + func 4 0.843 rtdm_fd_read+0x28 (CoBaLt_read+0x30) + func 4 0.843 get_fd_fixup_mode+0x1c (rtdm_fd_read+0x30) + func 5 0.960 rtdm_fd_get+0x24 (get_fd_fixup_mode+0x28) |+ begin 0x80000000 6 1.078 rtdm_fd_get+0x17c (<00000000>) |# func 7 1.019 ___xnlock_get+0x14 (rtdm_fd_get+0x6c) |# func 8 1.058 ___xnlock_put+0x14 (rtdm_fd_get+0x140) |# func 9 0.000 __ipipe_restore_head+0x20 (rtdm_fd_get+0xd4)