zdtm/static/fd failure on aarch64

Submitted by Dmitry Safonov on June 12, 2018, 3:13 p.m.

Details

Message ID CAJwJo6Y3Nv8TknPbBz0w_H-t5A6GzH7zS1W5P4+9zqSv+QQODw@mail.gmail.com
State New
Series "zdtm/static/fd failure on aarch64"
Headers show

Commit Message

Dmitry Safonov June 12, 2018, 3:13 p.m.
2018-06-12 7:48 GMT+01:00 Adrian Reber <adrian@lisas.de>:
> Output is always like this:
>
> 02:20:50.173: 11691: ERR: ../lib/lock.h:149: futex *0xffff86100000 = 0, c = 2249195520 (errno = 11 (Resource temporarily unavailable))
>
> 11691 mmap(NULL, 65536, PROT_READ|PROT_WRITE, MAP_SHARED|MAP_ANONYMOUS, -1, 0) = 0xffff86100000
> 11691 futex(0xffff86100000, FUTEX_WAIT, 2249195521, NULL) = -1 EAGAIN (Resource temporarily unavailable)
> 11691 brk(NULL)                         = 0x149f0000
> 11691 brk(0x14a20000)                   = 0x14a20000
> 11691 brk(NULL)                         = 0x14a20000
> 11691 openat(AT_FDCWD, "/etc/localtime", O_RDONLY|O_CLOEXEC) = 4
> 11691 fstat(4, {st_mode=S_IFREG|0644, st_size=3519, ...}) = 0
> 11691 fstat(4, {st_mode=S_IFREG|0644, st_size=3519, ...}) = 0
> 11691 mmap(NULL, 65536, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xffff860f0000
> 11691 read(4, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\4\0\0\0\4\0\0\0\0"..., 8192) = 3519
> 11691 lseek(4, -2252, SEEK_CUR)         = 1267
> 11691 read(4, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\5\0\0\0\5\0\0\0\0"..., 8192) = 2252
> 11691 close(4)                          = 0
> 11691 munmap(0xffff860f0000, 65536)     = 0
> 11691 write(2, "02:20:50.173: 11691: ERR: ../lib"..., 135) = 135
> 11691 futex(0xffff86100000, FUTEX_WAIT, 2249195521, NULL) = -1 EAGAIN (Resource temporarily unavailable)
> 11691 newfstatat(AT_FDCWD, "/etc/localtime", {st_mode=S_IFREG|0644, st_size=3519, ...}, 0) = 0
> 11691 write(2, "02:20:50.175: 11691: ERR: ../lib"..., 135) = 135
>
> How I understand it is that atomic_inc() should return the new value but the returned value
> is completely different from what atomic_get() returns, right?

Well, atomic_inc() should return the old value, AFAICS from code.
atomic_inc_return() should return the new value.

I think it's not due cast we've some garbage value, it looks as if
we're doing 16-bit operations on 32-bit values.. But we aren't as far
as I can catch from arm64 asm.

Could you try with this to see, if atomic ops work?
Probably also worth to try to zero-init `tmp'/`result' inside ops to check
if the result is garbage from the stack in ops function.

Patch hide | download patch | download mbox

diff --git a/test/zdtm/lib/lock.h b/test/zdtm/lib/lock.h
index 9c0831d461c1..97a23c4baec3 100644
--- a/test/zdtm/lib/lock.h
+++ b/test/zdtm/lib/lock.h
@@ -145,7 +145,10 @@  static void inline mutex_lock(mutex_t *m)
 	while ((c = atomic_inc(&m->raw)) != 0) {
 		ret = sys_futex(&m->raw, FUTEX_WAIT, c + 1, NULL, NULL, 0);
 		if (ret < 0)
-			pr_perror("futex");
+			pr_perror("futex *%p = %d, c = %u, +0 = %u, -0 = %u",
+				&m->raw, atomic_get(&m->raw),
+				c, atomic_add_return(0, &m->raw),
+				atomic_sub_return(0, &m->raw));
 		BUG_ON(ret < 0 && errno != EWOULDBLOCK);
 	}
 }

Comments

Adrian Reber June 12, 2018, 4:23 p.m.
On Tue, Jun 12, 2018 at 04:13:05PM +0100, Dmitry Safonov wrote:
> 2018-06-12 7:48 GMT+01:00 Adrian Reber <adrian@lisas.de>:
> > Output is always like this:
> >
> > 02:20:50.173: 11691: ERR: ../lib/lock.h:149: futex *0xffff86100000 = 0, c = 2249195520 (errno = 11 (Resource temporarily unavailable))
> >
> > 11691 mmap(NULL, 65536, PROT_READ|PROT_WRITE, MAP_SHARED|MAP_ANONYMOUS, -1, 0) = 0xffff86100000
> > 11691 futex(0xffff86100000, FUTEX_WAIT, 2249195521, NULL) = -1 EAGAIN (Resource temporarily unavailable)
> > 11691 brk(NULL)                         = 0x149f0000
> > 11691 brk(0x14a20000)                   = 0x14a20000
> > 11691 brk(NULL)                         = 0x14a20000
> > 11691 openat(AT_FDCWD, "/etc/localtime", O_RDONLY|O_CLOEXEC) = 4
> > 11691 fstat(4, {st_mode=S_IFREG|0644, st_size=3519, ...}) = 0
> > 11691 fstat(4, {st_mode=S_IFREG|0644, st_size=3519, ...}) = 0
> > 11691 mmap(NULL, 65536, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xffff860f0000
> > 11691 read(4, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\4\0\0\0\4\0\0\0\0"..., 8192) = 3519
> > 11691 lseek(4, -2252, SEEK_CUR)         = 1267
> > 11691 read(4, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\5\0\0\0\5\0\0\0\0"..., 8192) = 2252
> > 11691 close(4)                          = 0
> > 11691 munmap(0xffff860f0000, 65536)     = 0
> > 11691 write(2, "02:20:50.173: 11691: ERR: ../lib"..., 135) = 135
> > 11691 futex(0xffff86100000, FUTEX_WAIT, 2249195521, NULL) = -1 EAGAIN (Resource temporarily unavailable)
> > 11691 newfstatat(AT_FDCWD, "/etc/localtime", {st_mode=S_IFREG|0644, st_size=3519, ...}, 0) = 0
> > 11691 write(2, "02:20:50.175: 11691: ERR: ../lib"..., 135) = 135
> >
> > How I understand it is that atomic_inc() should return the new value but the returned value
> > is completely different from what atomic_get() returns, right?
> 
> Well, atomic_inc() should return the old value, AFAICS from code.
> atomic_inc_return() should return the new value.
> 
> I think it's not due cast we've some garbage value, it looks as if
> we're doing 16-bit operations on 32-bit values.. But we aren't as far
> as I can catch from arm64 asm.
> 
> Could you try with this to see, if atomic ops work?

11:47:58.974: 15442: ERR: ../lib/lock.h:152: futex *0xffffb1d50000 = 0, c = 2983526400, +0 = 2983526400, -0 = 2983526400 (errno = 11 (Resource temporarily unavailable))

Looks wrong. But looking at the lower bits of 0xffffb1d50000 I see that
0xb1d50000 is the same as 2983526400. So instead of the value we get the
lower bits of the address.

> Probably also worth to try to zero-init `tmp'/`result' inside ops to check
> if the result is garbage from the stack in ops function.

I already tried that, but it did not change anything.

		Adrian