The issue is with the test.
136/366 glib:gobject+performance+no-valgrind / performance
RUNNING
>>> MALLOC_CHECK_=2 MALLOC_PERTURB_=153 G_TEST_SRCDIR=/<<PKGBUILDDIR>>/gobject/tests/performance G_ENABLE_DIAGNOSTIC=1 G_DEBUG=gc-friendly
G_TEST_BUILDDIR=/<<PKGBUILDDIR>>/debian/build/deb/gobject/tests/performance
LD_LIBRARY_PATH=/<<PKGBUILDDIR>>/debian/build/deb/glib:/<<PKGBUILDDIR>>/debian/build/deb/gobject
/<<PKGBUILDDIR>>/debian/build/deb/gobject/tests/performance/performance --seconds 0
――――――――――――――――――――――――――――――――――――― ✀ ―――――――――――――――――――――――――――――――――――――
Running test simple-construction
Millions of constructed objects per second: 0.312
Running test simple-construction1
(performance:4588): GLib-ERROR **: 15:54:55.415: ../../../glib/gmem.c:470:
overflow allocating 2147483647*4 bytes
――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――
136/366 glib:gobject+performance+no-valgrind / performance
FAIL 7.49s killed by signal 5 SIGTRAP
Debugging this, I see this is caused by a timer issue:
/* Estimate time for one run by doing a few test rounds */
min_elapsed = 0;
for (i = 0; i < ESTIMATE_ROUND_TIME_N_RUNS; i++)
{
test->init (test, data, 1.0);
g_timer_start (timer);
test->run (test, data);
g_timer_stop (timer);
test->finish (test, data);
elapsed = g_timer_elapsed (timer, NULL);
if (i == 0)
min_elapsed = elapsed;
else
min_elapsed = MIN (min_elapsed, elapsed);
}
factor = TARGET_ROUND_TIME / min_elapsed;
g_timer_elapsed() uses g_get_monotonic_time():
gint64
g_get_monotonic_time (void)
{
struct timespec ts;
gint result;
result = clock_gettime (CLOCK_MONOTONIC, &ts);
if G_UNLIKELY (result != 0)
g_error ("GLib requires working CLOCK_MONOTONIC");
return (((gint64) ts.tv_sec) * 1000000) + (ts.tv_nsec / 1000);
}
The tick resolution of CLOCK_MONOTONIC is poor on SMP machines and it is
determined by CONFIG_HZ.
CONFIG_HZ= 100 on the machines where this occurs. The error does not occur on
UP machines where
CLOCK_MONOTONIC has the full accuracy of the CPU hardware timer.
The problem is g_timer_elapsed() returns zero in the first call in
simple-construction1. The test does not check
for zero returns. min_elapsed is set to zero and factor to inf. This factor
value causes the allocation overflow.
Here is strace output for test:
write(1, "Running test simple-construction"..., 34Running test
simple-construction1
) = 34
clock_gettime64(CLOCK_MONOTONIC, {tv_sec=431547, tv_nsec=711943581}) = 0
clock_gettime64(CLOCK_MONOTONIC, {tv_sec=431547, tv_nsec=711943581}) = 0
brk(0x68000) = 0x68000
clock_gettime64(CLOCK_MONOTONIC, {tv_sec=431547, tv_nsec=941941637}) = 0
clock_gettime64(CLOCK_MONOTONIC, {tv_sec=431547, tv_nsec=941941637}) = 0
clock_gettime64(CLOCK_MONOTONIC, {tv_sec=431547, tv_nsec=941941637}) = 0
clock_gettime64(CLOCK_MONOTONIC, {tv_sec=431547, tv_nsec=951941553}) = 0
clock_gettime64(CLOCK_MONOTONIC, {tv_sec=431547, tv_nsec=951941553}) = 0
clock_gettime64(CLOCK_MONOTONIC, {tv_sec=431547, tv_nsec=951941553}) = 0
clock_gettime64(CLOCK_MONOTONIC, {tv_sec=431547, tv_nsec=951941553}) = 0
clock_gettime64(CLOCK_MONOTONIC, {tv_sec=431547, tv_nsec=961941468}) = 0
clock_gettime64(CLOCK_MONOTONIC, {tv_sec=431547, tv_nsec=961941468}) = 0
clock_gettime64(CLOCK_MONOTONIC, {tv_sec=431547, tv_nsec=961941468}) = 0
clock_gettime64(CLOCK_MONOTONIC, {tv_sec=431547, tv_nsec=961941468}) = 0
getpeername(2, 0xf91ac888, [128]) = -1 ENOTSOCK (Socket operation on
non-socket)
futex_time64(0xf773de68, FUTEX_WAKE_PRIVATE, 2147483647) = 0
ioctl(2, TCGETS, {c_iflag=ICRNL|IXON|IMAXBEL, c_oflag=NL0|CR0|TAB0|BS0|VT0|FF0|OPOST|ONLCR, c_cflag=B38400|CS8|CREAD,
c_lflag=ISIG|ICANON|ECHO|ECHOE|ECHOK|IEXTEN|ECHOCTL|ECHOKE, ...}) = 0
getpid() = 17069
clock_gettime64(CLOCK_REALTIME, {tv_sec=1692049088, tv_nsec=309288398}) = 0
openat(AT_FDCWD, "/etc/localtime", O_RDONLY|O_CLOEXEC) = 3
statx(3, "", AT_STATX_SYNC_AS_STAT|AT_NO_AUTOMOUNT|AT_EMPTY_PATH, STATX_BASIC_STATS, {stx_mask=STATX_BASIC_STATS|STATX_MNT_ID, stx_attributes=0,
stx_mode=S_IFREG|0644, stx_size=114, ...}) = 0
statx(3, "", AT_STATX_SYNC_AS_STAT|AT_NO_AUTOMOUNT|AT_EMPTY_PATH, STATX_BASIC_STATS, {stx_mask=STATX_BASIC_STATS|STATX_MNT_ID, stx_attributes=0,
stx_mode=S_IFREG|0644, stx_size=114, ...}) = 0
read(3, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096)
= 114
_llseek(3, -60, [54], SEEK_CUR) = 0
read(3, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096)
= 60
close(3) = 0
brk(0x51000) = 0x51000
write(2, "\n(performance:17069): GLib-\33[1;3"..., 128
(performance:17069): GLib-ERROR **: 21:38:08.309: ../../../glib/gmem.c:470:
overflow allocating 2147483647*) = 128
write(2, "4 bytes\n", 84 bytes
) = 8
gettid() = 17069
getpid() = 17069
tgkill(17069, 17069, SIGTRAP) = 0
--- SIGTRAP {si_signo=SIGTRAP, si_code=SI_TKILL, si_pid=17069, si_uid=1000} ---
+++ killed by SIGTRAP (core dumped) +++
Trace/breakpoint trap
You can see that multiple calls to clock_gettime64() return the same result.
The attached change will fix the test but probably isn't ideal.
Regards,
Dave Anglin
--
John David Anglin [email protected]
--- ./gobject/tests/performance/performance.c.save 2023-08-14
21:59:41.728405583 +0000
+++ ./gobject/tests/performance/performance.c 2023-08-14 22:02:53.026806919
+0000
@@ -114,7 +114,10 @@
min_elapsed = MIN (min_elapsed, elapsed);
}
- factor = TARGET_ROUND_TIME / min_elapsed;
+ if (min_elapsed != 0.0)
+ factor = TARGET_ROUND_TIME / min_elapsed;
+ else
+ factor = 1.0;
if (verbose)
g_print ("Uncorrected round time: %.4f msecs, correction factor %.2f\n",
1000*min_elapsed, factor);
