From: chensong <chensong@kylinos.cn>
To: xenomai@xenomai.org
Subject: hith latency when cpu is fully loaded
Date: Tue, 19 Nov 2019 09:01:19 +0800 [thread overview]
Message-ID: <5DD33EDF.5040506@kylinos.cn> (raw)
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)
next reply other threads:[~2019-11-19 1:01 UTC|newest]
Thread overview: 5+ messages / expand[flat|nested] mbox.gz Atom feed top
2019-11-19 1:01 chensong [this message]
[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
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=5DD33EDF.5040506@kylinos.cn \
--to=chensong@kylinos.cn \
--cc=xenomai@xenomai.org \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
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.