sleep() for more than 2 seconds in my c project on my zedboard running petalinux is misbehaving. Here is the code.
#include <stdio.h>
#include <stdlib.h>
#include <unistd.h>
int main(){
printf("Main sleep\n");
sleep(3);
printf("Main wakeup\n");
fflush(stdout);
exit(0);
}
Sleep for 3 seconds and I do not see the wakeup print statement, nor does the program exit. I have to hit enter once or twice and then the program exits without printing wakeup. If I sleep for 2 seconds then the program behaves as expected.
Only reproducible on zedboard running petalinux. Same code compiled and running on my laptop does not have this strange behavior
I am connected to the zedboard via serial console. The serial device that the console is running on in the zedboard is the default /dev/ttyPS0
Edit: Changed the question, has nothing to do with multithreading. Added the most simple reproducible example
Edit: I added the following
#include <stdio.h>
#include <stdlib.h>
#include <unistd.h>
#include <time.h>
int main(){
time_t t = time(NULL);
struct tm tme = *localtime(&t);
printf("Main sleep at %d seconds\n", tme.tm_sec);
sleep(3);
t = time(NULL);
tme = *localtime(&t);
printf("Main wakeup at %d seconds\n", tme.tm_sec);
fflush(stdout);
exit(0);
}
I ran the program as so:
root@zed:~# ./payload-software > a.txt
The program did not exit until I hit enter, I waited 20 seconds. I cat the file and here is the result:
root@zed:~# cat a.txt
Main sleep at 35 seconds
Main wakeup at 38 seconds
Program is sleeping like it should but it is not exiting and it is not printing to stdout when I run it without file redirect. If i change sleep time to 2 seconds it works fine.
Edit: Add strace:
root@zed:~# strace payload-software
execve("/usr/bin/payload-software", ["payload-software"], 0xbe9f8dd0 /* 13 vars */) = 0
brk(NULL) = 0x4dd000
uname({sysname="Linux", nodename="zed", ...}) = 0
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=6146, ...}) = 0
mmap2(NULL, 6146, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb6f98000
close(3) = 0
openat(AT_FDCWD, "/lib/librt.so.1", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0@\33\0\0004\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=22176, ...}) = 0
mmap2(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6f96000
mmap2(NULL, 86248, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb6f5a000
mprotect(0xb6f5f000, 61440, PROT_NONE) = 0
mmap2(0xb6f6e000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x4000) = 0xb6f6e000
close(3) = 0
openat(AT_FDCWD, "/lib/libpthread.so.0", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0]V\0\0004\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=75704, ...}) = 0
mmap2(NULL, 147656, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb6f35000
mprotect(0xb6f47000, 61440, PROT_NONE) = 0
mmap2(0xb6f56000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x11000) = 0xb6f56000
mmap2(0xb6f58000, 4296, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb6f58000
close(3) = 0
openat(AT_FDCWD, "/lib/tls/v7l/neon/vfp/libc.so.6", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/lib/tls/v7l/neon/vfp", 0xbeab1178) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/tls/v7l/neon/libc.so.6", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/lib/tls/v7l/neon", 0xbeab1178) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/tls/v7l/vfp/libc.so.6", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/lib/tls/v7l/vfp", 0xbeab1178) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/tls/v7l/libc.so.6", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/lib/tls/v7l", 0xbeab1178) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/tls/neon/vfp/libc.so.6", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/lib/tls/neon/vfp", 0xbeab1178) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/tls/neon/libc.so.6", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/lib/tls/neon", 0xbeab1178) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/tls/vfp/libc.so.6", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/lib/tls/vfp", 0xbeab1178) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/tls/libc.so.6", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/lib/tls", 0xbeab1178) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/v7l/neon/vfp/libc.so.6", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/lib/v7l/neon/vfp", 0xbeab1178) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/v7l/neon/libc.so.6", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/lib/v7l/neon", 0xbeab1178) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/v7l/vfp/libc.so.6", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/lib/v7l/vfp", 0xbeab1178) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/v7l/libc.so.6", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/lib/v7l", 0xbeab1178) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/neon/vfp/libc.so.6", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/lib/neon/vfp", 0xbeab1178) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/neon/libc.so.6", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/lib/neon", 0xbeab1178) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/vfp/libc.so.6", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat64("/lib/vfp", 0xbeab1178) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/libc.so.6", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\211\260\1\0004\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=931444, ...}) = 0
mmap2(NULL, 1001036, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb6e40000
mprotect(0xb6f20000, 61440, PROT_NONE) = 0
mmap2(0xb6f2f000, 16384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0xdf000) = 0xb6f2f000
mmap2(0xb6f33000, 5708, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb6f33000
close(3) = 0
set_tls(0xb6f973f0) = 0
mprotect(0xb6f2f000, 8192, PROT_READ) = 0
mprotect(0xb6f56000, 4096, PROT_READ) = 0
mprotect(0xb6f6e000, 4096, PROT_READ) = 0
mprotect(0x4d4000, 4096, PROT_READ) = 0
mprotect(0xb6f9a000, 4096, PROT_READ) = 0
munmap(0xb6f98000, 6146) = 0
set_tid_address(0xb6f96f18) = 656
set_robust_list(0xb6f96f20, 12) = 0
rt_sigaction(SIGRTMIN, {sa_handler=0xb6f3a20d, sa_mask=[], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0xb6e6a291}, NULL, 8) = 0
rt_sigaction(SIGRT_1, {sa_handler=0xb6f3a291, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART|SA_SIGINFO, sa_restorer=0xb6e6a291}, NULL, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0
ugetrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM_INFINITY}) = 0
clock_gettime64(CLOCK_REALTIME_COARSE, {tv_sec=1520599284, tv_nsec=439968873}) = 0
brk(NULL) = 0x4dd000
brk(0x4fe000) = 0x4fe000
openat(AT_FDCWD, "/etc/localtime", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
fstat64(1, {st_mode=S_IFCHR|0600, st_rdev=makedev(0xfd, 0), ...}) = 0
ioctl(1, TCGETS, {B115200 opost isig icanon echo ...}) = 0
write(1, "Main sleep at 24 seconds\n", 25Main sleep at 24 seconds
) = 25
clock_nanosleep_time64(CLOCK_REALTIME, 0, {tv_sec=3, tv_nsec=3761122102560686080},
0xbeab1bd0) = 0
clock_gettime64(CLOCK_REALTIME_COARSE, {tv_sec=1520599287, tv_nsec=449968632}) = 0
openat(AT_FDCWD, "/etc/localtime", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
write(1, "Main wakeup at 27 seconds\n", 26Main wakeup at 27 seconds
) = 26
exit_group(0) = ?
+++ exited with 0 +++
Note, I had to once again repeatedly press enter to get the output after the call to sleep() to print.
The issue seems to be with the serial console of the zedboard. I noticed that the same issue was occurring at startup, a certain system call at startup was blocking for a bit to set something up and that was causing subsequent startup messages to not be shown. The console prompt wouldn't show up either until I hit enter, the exact same issue I was seeing with running the above code.
So it is something with the serial console that is going bad. Over ssh, the issue is not present. I am not sure if it is on my end (I am using screen) or on the zedboard end (it is using getty).
Anyway, not the end of the world, thank you all for your help.