kernel panic in pvfs2_devreq_read()

console screenshot

Some more information: there are 30 some odd clients accessing the file system, each has 8 application processes running. Two or three clients hit the problem at a time. There are two servers, both providing metadata and io.

It is possible that files are being deleted while they are being read or written, but it isn't clear if this has anything to do with triggering the panic condition.

User is going to try repeating the scenario with --desc-count set higher to rule out if there is a problem with contention on the bufmap resources.

Going to try a little mpi test program that does posix reads/writes to independent files from N-1 processes while the remaining process periodically deletes one of the files to see what happens if this is done on a single node.

Ran test program on a single node with 8 processes for a little bit. So far no unexpected behavior (or panics) on the client side. Messages like this appear in the kernel log:

[592767.940000] pvfs2_file_write: error in vectored write to handle 1048581, FILE: 1
[592767.940000]   -- returning -2

Unfortunately, the server crashed before it got very far, though. This is the backtrace from the server core file:

(gdb) where
#0  0xffffe410 in __kernel_vsyscall ()
#1  0xb7d01875 in raise () from /lib/tls/i686/cmov/libc.so.6
#2  0xb7d03201 in abort () from /lib/tls/i686/cmov/libc.so.6
#3  0xb7cfab6e in __assert_fail () from /lib/tls/i686/cmov/libc.so.6
#4  0x0808e86b in dbpf_open_cache_remove (coll_id=788611080, 
    handle=9223372036854765797)
    at ../pvfs2/src/io/trove/trove-dbpf/dbpf-open-cache.c:345
#5  0x0808fd81 in dbpf_dspace_remove_op_svc (op_p=0xb5dcd4f8)
    at ../pvfs2/src/io/trove/trove-dbpf/dbpf-dspace.c:422
#6  0x08093cd6 in dbpf_do_one_work_cycle (out_count=0xb7c873c8)
    at ../pvfs2/src/io/trove/trove-dbpf/dbpf-thread.c:194
#7  0x080939af in dbpf_thread_function (ptr=0x0)
    at ../pvfs2/src/io/trove/trove-dbpf/dbpf-thread.c:95
#8  0xb7e3046b in start_thread () from /lib/tls/i686/cmov/libpthread.so.0
#9  0xb7daa6de in clone () from /lib/tls/i686/cmov/libc.so.6

Can reproduce a little more reliably by starting a set of 4 scripts that each continuously use dd to write to the same file, and then rm'ing that file in another terminal.

If access,access_detail logging is turned on, then the final lines of the log file show that the request scheduler is allowing a remove operation to start while I/O is occurring on a file:

[A 11:39:03.650061] pcarns.pcarns@127.0.0.1 H=9223372036854765702 S=0x8160760: io: request
[A 11:39:03.650158] pcarns.pcarns@127.0.0.1 H=9223372036854765702 S=0x8160760: io: start
[A 11:39:03.658677] pcarns.pcarns@127.0.0.1 H=1048664 S=0x816f138: setattr: request
[A 11:39:03.658763] pcarns.pcarns@127.0.0.1 H=1048664 S=0x816f138: setattr: start
[A 11:39:04.540266] pcarns.pcarns@127.0.0.1 H=1048580 S=0x816e1d8: rmdirent: finish (Success)
[A 11:39:04.540965] pcarns.pcarns@127.0.0.1 H=1048664 S=0x816f138: setattr: finish (No such file or directory)
[A 11:39:04.542980] pcarns.pcarns@127.0.0.1 H=9223372036854765702 S=0x8173e18: remove: request
[A 11:39:04.543186] pcarns.pcarns@127.0.0.1 H=9223372036854765702 S=0x8173e18: remove: start

This is still pretty far from the original bug that I was trying to replicate, but it seems important to figure out while the scenario is reproducable. The request scheduler is not supposed to let this combination proceed.

Resolved request scheduler issue noted in the above comments. This turned out to be a trunk only bug that doesn't have anything to do with the original pvfs2_devreq_read() issue described in the ticket.

I can't reproduce this panic on my laptop, but looking closer at the console output there is a clue. The crash is happening in list_add(), which is only triggered for two data structures in pvfs2_devreq_read().

The first is pvfs2_request_list, but that one is protected in every kernel module use path by a spinlock.

The second is htable_ops_in_progress, which is not protected anywhere. htable_ops_in_progress can be modified in the pvfs2-client-core context (via the devreq functions) or in the application context (via clean_up_interrupted_operation()). There is therefore a race potential here.

User that reported this problem found it on a heavily loaded 8 core system.

Whoops. htable_ops_in_progress has an internal lock as part of qhash. Need to figure out if that has enough scope to protect it.

It looks like the purge_inprogress_ops() function walks the htable_ops_in_progress structure without holding a lock. However, I don't see any way for that function to be called at the same time as pvfs2_devreq_read(), because it only appears on device release. Must be something else going on.