Opened 9 years ago

Closed 9 years ago

#5878 closed bug (fixed)

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

Reported by: damoklas Owned by: axeld
Priority: normal Milestone: R1/alpha2
Component: File Systems/BFS Version: R1/Development
Keywords: Cc:
Blocked By: Blocking:
Has a Patch: no Platform: All

Description

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

Attachments (5)

restartos.jpg (375.4 KB) - added by damoklas 9 years ago.
And this by restarting OS
syslog (89.7 KB) - added by damoklas 9 years ago.
Syslog after boot
pictureiorequest.jpg (309.5 KB) - added by damoklas 9 years ago.
io_request (that right, what I make)
iorequestasbefore.jpg (307.1 KB) - added by damoklas 9 years ago.
io_request (as before), Haiku rev. 36542
iorequestandbt.jpg (351.8 KB) - added by damoklas 9 years ago.
io_request and bt <thread>

Download all attachments as: .zip

Change History (14)

Changed 9 years ago by damoklas

Attachment: restartos.jpg added

And this by restarting OS

comment:1 Changed 9 years ago by damoklas

Panic also when shutdown system.

comment:2 Changed 9 years ago by bonefish

Summary: Panic Kernel by quiting Tracker ir ProcessController[I/O Scheduler] rw_lock_read_unlock(): lock not read-locked
Version: R1/alpha1R1/Development

comment:3 Changed 9 years ago by 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.

Changed 9 years ago by damoklas

Attachment: syslog added

Syslog after boot

Changed 9 years ago by damoklas

Attachment: pictureiorequest.jpg added

io_request (that right, what I make)

comment:4 Changed 9 years ago by 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.

comment:5 Changed 9 years ago by 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!

Changed 9 years ago by damoklas

Attachment: iorequestasbefore.jpg added

io_request (as before), Haiku rev. 36542

Changed 9 years ago by damoklas

Attachment: iorequestandbt.jpg added

io_request and bt <thread>

comment:6 Changed 9 years ago by damoklas

That panic by quiting Tracker in ProcessController.

comment:7 Changed 9 years ago by bonefish

Component: System/KernelFile Systems/BFS

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

comment:8 Changed 9 years ago by axeld

Status: newin-progress

Calling me evildoer usually suffices ;-)

comment:9 Changed 9 years ago by axeld

Resolution: fixed
Status: in-progressclosed

Fixed in hrev36707.

Note: See TracTickets for help on using tickets.