All of lore.kernel.org
 help / color / mirror / Atom feed
* hith latency when cpu is fully loaded
@ 2019-11-19  1:01 chensong
  0 siblings, 0 replies; 5+ messages in thread
From: chensong @ 2019-11-19  1:01 UTC (permalink / raw)
  To: xenomai

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)






^ permalink raw reply	[flat|nested] 5+ messages in thread
end of thread, other threads:[~2019-11-19  8:23 UTC | newest]

Thread overview: 5+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
     [not found] <25135.7772549213$1574125359@news.gmane.org>
2019-11-19  6:49 ` hith latency when cpu is fully loaded Jan Kiszka
2019-11-19  7:45   ` chensong
2019-11-19  8:03     ` Jan Kiszka
2019-11-19  8:23       ` chensong
2019-11-19  1:01 chensong

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.