[I/O Scheduler] rw_lock_read_unlock(): lock not read-locked

[damoklas]

By quiting Tracker in ProcessController. Tested on haiku-r1a2-rc-hrev36542. ​http://dev.haiku-os.org/attachment/ticket/2557/panicbyquittrackerinpcontr.jpg

[damoklas]

And this by restarting OS

[damoklas]

Panic also when shutdown system.

[bonefish]

Mmh, I've never seen this myself before. I wonder why it happens so often on your machine. Could you add a syslog from directly after booting, please. Did you do anything special with respect to disks? Any USB disk plugging/unplugging?

When you run into the bug next, it would be great, if you could execute a few more kernel debugger commands that might provide helpful info. When you have a look at the stack trace, there are lines containing IORequest<...> with a green number between the pointy braces. Two different numbers in in total. For each of them please execute the following:

• io_request <request> (replace <request> by the number).
• io_request_owner <owner> (replace <owner> by the number the first command printed after owner:, unless that was 0x00000000).

BTW, in most cases when being dropped into KDL a stack trace is printed automatically -- if that one is fully visible, there's no need to type "bt" in such a case.

[damoklas]

Syslog after boot

[damoklas]

io_request (that right, what I make)

[damoklas]

Maybe these kernel fall began after I started to connect the USB digital camera, because before that I successfully Shut down the OS, but now every shutdown or reboot the system causes the fall of the kernel.

[bonefish]

So far things look OK. My analysis so far:

• The outer IORequest is a read at offset 0, size 4096.
• The request is passed to bfs_io(), which read-locks the vnode and passes the request on to do_iterative_fd_io().
• do_iterative_fd_io() creates a subrequest via do_iterative_fd_io_iterate(). The subrequest is only 2048 bytes long and the outer request is only advanced that far, which means that BFS's iterative_io_get_vecs_hook() returned only a single vector of this size. The file is obviously <= 2 KB in size.
• The subrequest is satisfied by the I/O scheduler, its NotifyFinished() is invoked with B_OK and it calls the parent request's SubRequestFinished() with status = B_OK, partialTransfer = false, and transferEndOffset = 2048.
• SubRequestFinished() determines that this is the last pending subrequest and calls NotifyFinished(B_OK). Since the subrequest succeeded fully, the request's fPartialTransfer remains false.
• NotifyFinished() determines the request as not yet fully finished (fStatus == B_OK && !fPartialTransfer && RemainingBytes() > 0). Hence it calls the iteration callback to get more subrequests. iterative_io_get_vecs_hook() cannot get any vectors and thus returns B_OK and _partialTransfer = true. Therefore the request's fPartialTransfer is set to true and NotifyFinished() falls through to actually finish the request.
• The finished callback, do_iterative_fd_io_finish(), is called, which in turn calls BFS's iterative_io_finished_hook() that read-unlocks the vnode.

For some reason the vnode has already been unlocked at that point, which triggers the panic(). I've added an assert to ensure that NotifyRequest() is not called twice in hrev36594 (trunk).

damoklas, when you encounter it again, could do the following, please:

• Execute io_request as before. io_request_owner won't be needed.
• The io_request prints a line with thread: and the number of the responsible thread (104 in screenshot you attached). Run bt <thread> (replace <thread> by the thread number) to print a stack trace for that thread. The output might be longer and overwrite the previous one, so better take a screenshot before.

Thanks!

[damoklas]

io_request (as before), Haiku rev. 36542

[damoklas]

io_request and bt <thread>

[damoklas]

That panic by quiting Tracker in ProcessController.

[bonefish]

Thanks, that unveils the ​evildoer (write lock held while calling file_cache_read()). Axel, are you listening?

[axeld]

Calling me evildoer usually suffices ;-)

[axeld]

Fixed in hrev36707.