hith latency when cpu is fully loaded

Mon, 18 Nov 2019 17:02:42 -0800 

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 <stdio.h>
#include <stdlib.h>
#include <sys/types.h>
#include <sys/wait.h>
#include <sys/stat.h>
#include <fcntl.h>

#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)

Reply via email to