time64 issue in simple program on 32-bit arm, linux 5.6

[jackschmidt]

Using musl-cross-make 5086175 (Mar 6th 2020) the following program produces incorrect (erratic) results on arm hardware with linux kernel 5.6 (but correct results on 32-bit arm kernel 4.19, correct results in qemu, and correct results on 32-bit arm kernel 5.6 if compiled with debian's gcc+glibc).

Program

#include <stddef.h>
#include <stdio.h>
#include <string.h>
#include <sys/time.h>
#include <time.h>

int main(int argc, char**argv) {
  struct timeval tv[1];
  struct timespec ts[1];

  gettimeofday(tv,NULL);
  clock_gettime(CLOCK_REALTIME,ts);

  printf(
    "tv:%lld %lld\n"
    "ts:%lld %lld\n"
    "--:%lld %lld\n",
    (long long) tv->tv_sec,
    (long long) tv->tv_usec,
    (long long) ts->tv_sec,
    (long long) ts->tv_nsec,
    (long long) ts->tv_sec - (long long) tv->tv_sec,
    (long long) ts->tv_nsec - 1000*(long long) tv->tv_usec
  );
}

compiled with:

$ ./output/bin/arm-pi-linux-musleabihf-gcc -o gettimeofday gettimeofday.c -static

Expected

Something like this is produced in qemu and on arm hardware running kernel 4.19. When running on arm hardware with kernel 5.6, the actual results are erratic. Notice the first integers (seconds) agree, and the second integers are close, after multiplying the top by 1000 (microseconds vs nanoseconds).

tv:1587832830 10420
ts:1587832830 10424132
--:0 4132

Actual

When running on actual arm hardware with kernel 5.6, the following are illustrative. Notice the seconds don't agree with each other and running the program one second later, the seconds have not incremented by 1.

$ ./gettimeofday
tv:1591345252 598823
ts:1591513022 608443869
--:167770 9620869
$ ./gettimeofday
tv:1598391378 945053
ts:1599062458 983533319
--:671080 38480319
$ ./gettimeofday
tv:1597048790 805053
ts:1597719870 843533242
--:671080 38480242

config.mak

TARGET = arm-pi-linux-musleabihf
COMMON_CONFIG += CFLAGS="-g0 -Os" CXXFLAGS="-g0 -Os" LDFLAGS="-s"
COMMON_CONFIG += --with-debug-prefix-map=$(CURDIR)=
GCC_CONFIG += --enable-languages=c
GCC_CONFIG += --with-cpu=cortex-a53

I ran make clean and then make install (and waited a while). The build host is a stock arch linux on x86_64.

[richfelker]

You should probably raise this issue on the musl list, as it's almost certainly not something specific to the toolchain build system. It may be a kernel bug. Have you run strace to see if actual syscalls or vdso is being used?

[richfelker]

Also can you try with just two successive calls to clock_gettime in the same program? gettimeofday is just a thin wrapper around clock_gettime so if there's a kernel bug causing erratic results you should see it without bringing in gettimeofday. If it only happens with joint use of clock_gettime and gettimeofday there may be a gcc bug causing something to get miscompiled.

[richfelker]

Also, by qemu do you mean qemu user-level emulation, or system emulation? (If the latter, what kernel?)

[jackschmidt]

kernel bug: glibc is ok, so I'm assuming the kernel is basically ok.
syscall: I think vdso, but I'm not an expert. strace attached below. (gcc+glibc appears to be using the syscall)
successive: still erratic
qemu: qemu user level (just testing it on the build machine)

New program

#include <stddef.h>
#include <stdio.h>
#include <string.h>
#include <sys/time.h>
#include <time.h>

int main(int argc, char**argv) {
  struct timespec ts[2];

  clock_gettime(CLOCK_REALTIME,&ts[0]);
  clock_gettime(CLOCK_REALTIME,&ts[1]);

  printf(
    "0:%lld %lld\n"
    "1:%lld %lld\n"
    "-:%lld %lld\n",
    (long long) ts[0].tv_sec,
    (long long) ts[0].tv_nsec,
    (long long) ts[1].tv_sec,
    (long long) ts[1].tv_nsec,
    (long long) ts[1].tv_sec - (long long) ts[0].tv_sec,
    (long long) ts[1].tv_nsec - (long long) ts[0].tv_nsec
  );
}

Expected

Here is a run on the program compiled by debian's gcc (with glibc):

$ gcc clock_gettime.c -static && ./a.out && strace ./a.out
0:1587852133 616994685
1:1587852133 616996259
-:0 1574
execve("./a.out", ["./a.out"], 0xbeaaedc0 /* 15 vars */) = 0
brk(NULL)                               = 0xc9a000
brk(0xc9ad08)                           = 0xc9ad08
set_tls(0xc9a4c0)                       = 0
uname({sysname="Linux", nodename="raspberrypi", ...}) = 0
readlink("/proc/self/exe", "/home/pi/a.out", 4096) = 14
brk(0xcbbd08)                           = 0xcbbd08
brk(0xcbc000)                           = 0xcbc000
clock_gettime(CLOCK_REALTIME, {tv_sec=1587852133, tv_nsec=635641041}) = 0
clock_gettime(CLOCK_REALTIME, {tv_sec=1587852133, tv_nsec=635912000}) = 0
fstat64(1, {st_mode=S_IFCHR|0600, st_rdev=makedev(0x4, 0x40), ...}) = 0
ioctl(1, TCGETS, {B115200 opost isig icanon echo ...}) = 0
write(1, "0:1587852133 635641041\n", 230:1587852133 635641041
) = 23
write(1, "1:1587852133 635912000\n", 231:1587852133 635912000
) = 23
write(1, "-:0 270959\n", 11-:0 270959
)            = 11
exit_group(0)                           = ?
+++ exited with 0 +++

On a 32-bit arm system using kernel 5.1 the output is similar (though no strace available).

Actual

Building with the same musl-cross-make toolchain (just to let you know the compiler setup is reproducible)

$ ./output/bin/arm-pi-linux-musleabihf -o clock_gettime clock_gettime.c -static

And then running on kernel 5.6 on 32 bit arm hardware:

$ ./clock_gettime && strace ./clock_gettime
0:1597599551 811233074
1:1598270631 916673074
-:671080 105440000
execve("./clock_gettime", ["./clock_gettime"], 0xbed63dc0 /* 15 vars */) = 0
set_tls(0x25554)                        = 0
set_tid_address(0x25604)                = 1270
ioctl(1, TIOCGWINSZ, {ws_row=24, ws_col=80, ws_xpixel=0, ws_ypixel=0}) = 0
writev(1, [{iov_base="0:1599277252 74833074", iov_len=21}, {iov_base="\n", iov_len=1}], 20:1599277252 74833074
) = 22
writev(1, [{iov_base="1:1600116102 206633074", iov_len=22}, {iov_base="\n", iov_len=1}], 21:1600116102 206633074
) = 23
writev(1, [{iov_base="-:838850 131800000", iov_len=18}, {iov_base="\n", iov_len=1}], 2-:838850 131800000
) = 19
exit_group(0)                           = ?
+++ exited with 0 +++

[richfelker]

glibc has 32-bit time, so "glibc is ok" doesn't say anything about whether the kernel is broken.

[richfelker]

And yes, your strace shows that vdso is being used, and apparently it's buggy and producing wrong results (scaling the clock counter by something way too large or accessing the 64-bit value in the wrong way or something similar).

[jackschmidt]

I wrote one that just uses the syscall pretty directly, and it appears to work well. Seconds go up by 1 about once per second :-)

Program

#include <stdio.h>
#include <unistd.h>
#include <time.h>
#include <syscall.h>

int main(int argc, char**argv) {
  struct timespec ts[1];
  syscall(SYS_clock_gettime64, CLOCK_REALTIME, ts);
  printf("sc: %lld %lld\n",
    (long long) ts->tv_sec, (long long) ts->tv_nsec
  );
}

Actual = Expected

Notice seconds go up by one after waiting one second.

$ ./syscall
sc: 1587855857 652015087
$ ./syscall
sc: 1587855858 711929367
$ strace ./syscall
strace ./syscall
execve("./syscall", ["./syscall"], 0xbe8e3dc0 /* 15 vars */) = 0
set_tls(0x2554c)                        = 0
set_tid_address(0x255fc)                = 1419
clock_gettime64(CLOCK_REALTIME, {tv_sec=1587855990, tv_nsec=934739267}) = 0
ioctl(1, TIOCGWINSZ, {ws_row=24, ws_col=80, ws_xpixel=0, ws_ypixel=0}) = 0
writev(1, [{iov_base="sc: 1587855990 934739267", iov_len=24}, {iov_base="\n", iov_len=1}], 2sc: 1587855990 934739267
) = 25
exit_group(0)                           = ?
+++ exited with 0 +++

I bet I've done something wrong since glibc crashes:

gcc syscall.c -static && ( ./a.out ; strace ./a.out )
sc: 1587855949 0
execve("./a.out", ["./a.out"], 0xbe840dc0 /* 15 vars */) = 0
brk(NULL)                               = 0x1cb7000
brk(0x1cb7d08)                          = 0x1cb7d08
set_tls(0x1cb74c0)                      = 0
uname({sysname="Linux", nodename="raspberrypi", ...}) = 0
readlink("/proc/self/exe", "/home/pi/a.out", 4096) = 14
brk(0x1cd8d08)                          = 0x1cd8d08
brk(0x1cd9000)                          = 0x1cd9000
clock_gettime64(CLOCK_REALTIME, {tv_sec=1587855949, tv_nsec=909458135}) = 0
fstat64(1, {st_mode=S_IFCHR|0600, st_rdev=makedev(0x4, 0x40), ...}) = 0
ioctl(1, TCGETS, {B115200 opost isig icanon echo ...}) = 0
write(1, "sc: 1587855949 0\n", 17sc: 1587855949 0
)      = 17
--- SIGSEGV {si_signo=SIGSEGV, si_code=SEGV_MAPERR, si_addr=NULL} ---
+++ killed by SIGSEGV +++

[jackschmidt]

Do you think the kernel is putting wrong things in vdso or is musl misinterpreting the contents?

Is there a simple way to help debug that?

The kernel itself is more or less "make defconfig".

[richfelker]

VDSO is just functions the kernel exports. The kernel is definitely buggy. We need to figure out how this is going to get fixed in a way that buggy ones don't get used which will require coordination with kernel folks...

[jackschmidt]

Ok. I tried on a very default kernel for the hardware. Same behavior. I checked the hex version of the time, and didn't see any obvious patterns.

Reproducible kernel

kernel is:
85313d9203e26197d536938b47e983509f5f0e55 from https://github.com/raspberrypi/linux.git tag rpi-5.6.y

hardware is stock raspberry pi 4b rev 1.2

Basically, this is just following the instructions at https://www.raspberrypi.org/documentation/linux/kernel/building.md

make O=../build ARCH=arm CROSS_COMPILE=arm-pi-linux-musleabihf- bcm2711_defconfig
make O=../build ARCH=arm CROSS_COMPILE=arm-pi-linux-musleabihf- -j 12
scp ../build/arch/arm/boot/zImage root@raspberrypi:/boot/kernel7l.img

Hex version of syscall vs vdso

I checked that it is probably not a bit-issue:

#include <stdio.h>
#include <unistd.h>
#include <time.h>
#include <syscall.h>

int main(int argc, char**argv) {
  struct timespec ts_sc[1];
  struct timespec ts_vd[1];
  syscall(SYS_clock_gettime64, CLOCK_REALTIME, ts_sc);
  clock_gettime(CLOCK_REALTIME, ts_vd);
  printf(
    "vd: %lld %lld (%llx %llx)\n"
    "sc: %lld %lld (%llx %llx)\n",
    (long long) ts_vd->tv_sec, (long long) ts_vd->tv_nsec,
    (long long) ts_vd->tv_sec, (long long) ts_vd->tv_nsec,
    (long long) ts_sc->tv_sec, (long long) ts_sc->tv_nsec,
    (long long) ts_sc->tv_sec, (long long) ts_sc->tv_nsec
  );
}

has output:

vd: 1591747555 564473013 (5ee023e3 21a52cb5)
sc: 1587859309 235420490 (5ea4cf6d e083b4a)
$ ./mix
vd: 1601142725 717573980 (5f6f7fc5 2ac54f5c)
sc: 1587859309 795288048 (5ea4cf6d 2f6721f0)
$ ./mix
vd: 1592586284 617427567 (5eecf02c 24cd326f)
sc: 1587859310 285230079 (5ea4cf6e 110043ff)
$ ./mix
vd: 1601142600 356267567 (5f6f7f48 153c362f)
sc: 1587859310 795231832 (5ea4cf6e 2f664658)
$ ./mix
vd: 1592921701 139135401 (5ef20e65 84b09a9)
sc: 1587859311 305248550 (5ea4cf6f 1231b926)

[richfelker]

Yes, it's not at all surprising that the bug is present in the default kernel for the hardware. Nobody else (i.e. not glibc) is using 64-bit time so it's not expected that anyone else would have noticed the bug because the bug is in an interface they're not using. We're going to have to drop support for vdso clock_gettime on ARM until there's a fix that makes it possible to reliably detect that the vdso isn't broken (such a fix would require new symbol name or version when re-enabling it anyway, I think).

You can apply this fix locally just by removing all of the VDSO_* macros from arch/arm/syscall_arch.h. I'll probably drop that as a patch for musl 1.2.0 into musl-cross-make.

[richfelker]

Should be fixed in mcm by d6ded50. This still needs further action for kernel fix and upstream musl to avoid using broken vdso so I won't be closing the issue here until the report is acked/handed-off there.

[jackschmidt]

Thank you! The fix works for me.

[richfelker]

Thanks for confirming.

[willdeacon]

Has this been reported to the kernel developers (linux-arm-kernel@lists.infradead.org)? I couldn't see anything in the archives.

[richfelker]

Thanks for the ping. I'll check.

[nsz-arm]

@jackschmidt can you bulid this code and run it on the kernel where you observed the issue and send us vdso.so:

#include <stdio.h>
#include <sys/auxv.h>
int main()
{
        void *p = (void*)getauxval(AT_SYSINFO_EHDR);
        FILE *f = fopen("vdso.so","w");
        fwrite(p, 4096, 1, f);
}

also please confirm that the exact same kernel works in qemu-system-arm with musl (before the vdso usage was reverted) and the bug is only reproducible on rpi hw (which means this is likely a hw bug).

[nsz-arm]

@jackschmidt please explain what that patch is?
are you saying you are using a broken modified kernel with non-upstream patches?
so far only you could reproduce the bug you reported that's why we expect it's an issue with your hw, but if you have modified kernel that may be an issue too.

[nsz-arm]

@jackschmidt what makes you think it affects other hw? i don't see the problem on a cortex a72 with same toolchain and 5.6 arm 32bit kernel, i'm building the rpi kernel now, but i wont be able to test the exact same setup as that's rpi specific (but i dont see there anything that would change vdso time64 behaviour compared to upstream 5.6 kernel).

[jackschmidt]

vdso.so attached (gzip'd only because github required it)

Let me know if you want me to change CLOCK_REALTIME to another value, or send the entire kernel (and if so, do you want the modules).

vdso.so.gz

[richfelker]

OK, @jackschmidt uncovered something useful even if not explaining it well. There's a function in the arm kernel code that kills the vdso functions if the virtual counter is missing. It's documented in comments as just being an optimization, to avoid going through a codepath that will fail. But I wonder if the code was actually broken. Without the above-cited patch from #96 (comment), (knaerzche/LibreELEC.tv@3efb847) the time64 version of the function was not suppressed.

[jackschmidt]

Yes, sorry. I suspect I was misreading @nsz-arm's messages. I don't use KODI, but it is a very popular arm OS, and libreelec is a popular way to run kodi on single board computers other than raspberry pi. They had a patch mentioned at raspberrypi/linux#3579 (comment) -- so credit to @popcornmix

[richfelker]

OK, that theory matches the vdso.so @jackschmidt shared. It has __vdso_clock_getres and __vdso_clock_gettime64 symbols but the rest have all been patched out (in a broken way that leaves their symbol versions in place).

[richfelker]

Symbol table '.dynsym' contains 6 entries:
   Num:    Value  Size Type    Bind   Vis      Ndx Name
     0: 00000000     0 NOTYPE  LOCAL  DEFAULT  UND 
     1: 00000000     0 OBJECT  GLOBAL DEFAULT  ABS LINUX_2.6
     2: 00000578   448 FUNC    GLOBAL DEFAULT    9 @@LINUX_2.6
     3: 00000738   128 FUNC    GLOBAL DEFAULT    9 __vdso_clock_getres@@LINUX_2.6
     4: 00000544    52 FUNC    GLOBAL DEFAULT    9 __vdso_clock_gettime64@@LINUX_2.6
     5: 000004f0    84 FUNC    GLOBAL DEFAULT    9 @@LINUX_2.6