Project

General

Profile

Bug #63422 ยป librbd.log

Joshua Baergen, 11/03/2023 08:35 PM

 
2023-11-03T20:18:17.209+0000 7f3127851240 20 librbd::api::Io aio_discard: ictx=0x55736a5e4f60, completion=0x55736ae829f0, off=268439552, len=8388608
2023-11-03T20:18:17.209+0000 7f3127851240 20 librbd::io::Dispatcher: 0x55736a62d7a0 send: dispatch_spec=0x55736a405e90
2023-11-03T20:18:17.209+0000 7f3127851240 20 librbd::io::QueueImageDispatch: 0x55736a62c1e0 discard: tid=73716
2023-11-03T20:18:17.209+0000 7f3127851240 20 librbd::io::FlushTracker: 0x55736a3a50b0 start_io: tid=73716, flush_tid=67465
2023-11-03T20:18:17.209+0000 7f31177fe700 20 librbd::io::Dispatcher: 0x55736a62d7a0 send: dispatch_spec=0x55736a405e90
2023-11-03T20:18:17.209+0000 7f31177fe700 20 librbd::io::QosImageDispatch: 0x55736a62d5d0 discard: tid=73716, image_extents=[268439552,8388608]
2023-11-03T20:18:17.209+0000 7f31177fe700 20 librbd::io::FlushTracker: 0x55736a3fea00 start_io: tid=73716, flush_tid=67465
2023-11-03T20:18:17.209+0000 7f31177fe700 20 librbd::exclusive_lock::ImageDispatch: 0x7f30fc000db0 discard: tid=73716, image_extents=[268439552,8388608]
2023-11-03T20:18:17.209+0000 7f31177fe700 20 librbd::io::RefreshImageDispatch: 0x55736a62c120 discard: tid=73716, image_extents=[268439552,8388608]
2023-11-03T20:18:17.209+0000 7f31177fe700 20 librbd::io::WriteBlockImageDispatch: 0x55736a457b50 discard: tid=73716
2023-11-03T20:18:17.209+0000 7f31177fe700 20 librbd::io::ImageDispatch: 0x55736a62c360 discard: image_extents=[268439552,8388608]
2023-11-03T20:18:17.209+0000 7f31177fe700 20 librbd::io::AsyncOperation: 0x55736ae82b00 start_op
2023-11-03T20:18:17.209+0000 7f31177fe700 20 librbd::io::ImageRequest: 0x7f31177f9fb0 send: aio_discard: ictx=0x55736a5e4f60, completion=0x55736ae829f0
2023-11-03T20:18:17.209+0000 7f31177fe700 20 librbd::io::AioCompletion: 0x55736ae829f0 set_request_count: pending=2
2023-11-03T20:18:17.209+0000 7f31177fe700 20 librbd::Journal: 0x7f3108013c10 append_io_events: event=AioDiscard, offset=268500992, length=4128768, flush=0, tid=132077
2023-11-03T20:18:17.209+0000 7f31177fe700 20 librbd::Journal: 0x7f3108013c10 append_io_events: event=AioDiscard, offset=272629760, length=4194304, flush=0, tid=132078
2023-11-03T20:18:17.209+0000 7f31177fe700 20 librbd::io::ImageRequest: 0x7f31177f9fb0 send_object_requests: rbd_data.020083acd075a3.0000000000000040 65536~4128768 from [0,4190208]
2023-11-03T20:18:17.209+0000 7f31177fe700 20 librbd::io::Dispatcher: 0x55736a62bc60 send: dispatch_spec=0x55736a7ec9d0
2023-11-03T20:18:17.209+0000 7f31177fe700 20 librbd::cache::WriteAroundObjectDispatch: 0x7f30fc001100 discard: rbd_data.020083acd075a3.0000000000000040 65536~4128768
2023-11-03T20:18:17.209+0000 7f31177fe700 20 librbd::cache::WriteAroundObjectDispatch: 0x7f30fc001100 dispatch_io: blocked on overlap: tid=134709
2023-11-03T20:18:17.209+0000 7f31177fe700 20 librbd::io::ImageRequest: 0x7f31177f9fb0 send_object_requests: rbd_data.020083acd075a3.0000000000000041 0~4194304 from [4190208,4194304]
2023-11-03T20:18:17.209+0000 7f31177fe700 20 librbd::io::Dispatcher: 0x55736a62bc60 send: dispatch_spec=0x55736a64fb80
2023-11-03T20:18:17.209+0000 7f31177fe700 20 librbd::cache::WriteAroundObjectDispatch: 0x7f30fc001100 discard: rbd_data.020083acd075a3.0000000000000041 0~4194304
2023-11-03T20:18:17.209+0000 7f31177fe700 20 librbd::cache::WriteAroundObjectDispatch: 0x7f30fc001100 dispatch_io: dispatching: tid=134710
2023-11-03T20:18:17.209+0000 7f31177fe700 20 librbd::io::Dispatcher: 0x55736a62bc60 send: dispatch_spec=0x55736a64fb80
2023-11-03T20:18:17.209+0000 7f31177fe700 20 librbd::journal::ObjectDispatch: 0x7f30fc011cf0 discard: rbd_data.020083acd075a3.0000000000000041 0~4194304
2023-11-03T20:18:17.209+0000 7f31177fe700 20 librbd::journal::ObjectDispatch: 0x7f30fc011cf0 wait_or_flush_event: journal_tid=132078
2023-11-03T20:18:17.209+0000 7f31177fe700 20 librbd::Journal: 0x7f3108013c10 wait_event: tid=132078, on_safe=0x55736a64fb80
2023-11-03T20:18:17.209+0000 7f31177fe700 20 librbd::io::AioCompletion: 0x55736ae829f0 complete_request: cb=1, pending=1
2023-11-03T20:18:17.209+0000 7f31177fe700 20 librbd::object_map::UpdateRequest: 0x7f3109307280 handle_update_object_map: r=0
2023-11-03T20:18:17.209+0000 7f31177fe700 20 librbd::object_map::UpdateRequest: 0x7f3109307280 update_in_memory_object_map:
2023-11-03T20:18:17.209+0000 7f31177fe700 20 librbd::object_map::Request: 0x7f3109307280 should_complete: r=0
2023-11-03T20:18:17.209+0000 7f31177fe700 20 librbd::ObjectMap: 0x55736a40dec0 handle_detained_aio_update: cell=0x7f30fc010e10, r=0
2023-11-03T20:18:17.209+0000 7f31177fe700 20 librbd::BlockGuard: 0x7f30fc0018b0 release: [block_start = 63, block_end = 64), pending_ops=0
2023-11-03T20:18:17.209+0000 7f31177fe700 20 librbd::io::ObjectRequest: 0x7f31092fbeb0 handle_pre_write_object_map_update: rbd_data.020083acd075a3.000000000000003f r=0
2023-11-03T20:18:17.209+0000 7f31177fe700 20 librbd::io::ObjectRequest: 0x7f31092fbeb0 write_object: rbd_data.020083acd075a3.000000000000003f
2023-11-03T20:18:17.209+0000 7f31177fe700 20 librbd::Journal: 0x7f3108013c10 handle_io_event_safe: r=0, tid=132077
2023-11-03T20:18:17.209+0000 7f31177fe700 20 librbd::Journal: 0x7f3108013c10 handle_io_event_safe: completing tid=132077
2023-11-03T20:18:17.209+0000 7f3116ffd700 20 librbd::io::ObjectRequest: 0x7f31092fbeb0 handle_write_object: rbd_data.020083acd075a3.000000000000003f r=0
2023-11-03T20:18:17.213+0000 7f3116ffd700 20 librbd::io::ObjectRequest: 0x7f31092fbeb0 post_write_object_map_update: rbd_data.020083acd075a3.000000000000003f
2023-11-03T20:18:17.213+0000 7f3116ffd700 20 librbd::ManagedLock: 0x7f30fc002258 is_lock_owner: =1
2023-11-03T20:18:17.213+0000 7f3116ffd700 20 librbd::ObjectMap: 0x55736a40dec0 detained_aio_update:
2023-11-03T20:18:17.213+0000 7f3116ffd700 20 librbd::BlockGuard: 0x7f30fc0018b0 detain: [block_start = 63, block_end = 64), free_slots=7
2023-11-03T20:18:17.213+0000 7f3116ffd700 20 librbd::ObjectMap: 0x55736a40dec0 detained_aio_update: in-flight update cell: 0x7f30fc010e68
2023-11-03T20:18:17.213+0000 7f3116ffd700 20 librbd::ManagedLock: 0x7f30fc002258 is_lock_owner: =1
2023-11-03T20:18:17.213+0000 7f3116ffd700 20 librbd::ObjectMap: 0x55736a40dec0 aio_update: start=63, end=64, 2->0
2023-11-03T20:18:17.213+0000 7f3116ffd700 20 librbd::object_map::UpdateRequest: 0x7f30fd2997d0 update_object_map: ictx=0x55736a5e4f60, oid=rbd_object_map.020083acd075a3, [63,64) = 2->0
2023-11-03T20:18:17.213+0000 7f3116ffd700 20 librbd::Journal: 0x7f3108013c10 handle_io_event_safe: r=0, tid=132078
2023-11-03T20:18:17.213+0000 7f3116ffd700 20 librbd::Journal: 0x7f3108013c10 handle_io_event_safe: completing tid=132078
2023-11-03T20:18:17.213+0000 7f3116ffd700 20 librbd::io::Dispatcher: 0x55736a62bc60 send: dispatch_spec=0x55736a64fb80
2023-11-03T20:18:17.213+0000 7f3116ffd700 20 librbd::io::SimpleSchedulerObjectDispatch: 0x7f30fc001fc0 discard: rbd_data.020083acd075a3.0000000000000041 0~4194304
2023-11-03T20:18:17.213+0000 7f3116ffd700 20 librbd::io::SimpleSchedulerObjectDispatch: 0x7f30fc001fc0 dispatch_delayed_requests: object_no=65: not found
2023-11-03T20:18:17.213+0000 7f3116ffd700 20 librbd::io::FlushTracker: 0x7f310801a670 start_io: tid=134700, flush_tid=134700
2023-11-03T20:18:17.213+0000 7f3116ffd700 20 librbd::io::ObjectDispatch: 0x55736a62bee0 discard: rbd_data.020083acd075a3.0000000000000041 0~4194304
2023-11-03T20:18:17.213+0000 7f3116ffd700 20 librbd::io::ObjectRequest: 0x7f30fd29ca70 send: rbd_data.020083acd075a3.0000000000000041 remove 0~4194304
2023-11-03T20:18:17.213+0000 7f3116ffd700 20 librbd::ManagedLock: 0x7f30fc002258 is_lock_owner: =1
2023-11-03T20:18:17.213+0000 7f3116ffd700 20 librbd::ObjectMap: 0x55736a40dec0 object_may_exist: object_no=65 r=0
2023-11-03T20:18:17.213+0000 7f3116ffd700 20 librbd::io::ObjectRequest: 0x7f30fd29ca70 send: rbd_data.020083acd075a3.0000000000000041 skipping no-op on nonexistent object
2023-11-03T20:18:17.213+0000 7f3116ffd700 20 librbd::io::ObjectRequest: 0x7f30fd29ca70 async_finish: rbd_data.020083acd075a3.0000000000000041 r=0
2023-11-03T20:18:17.213+0000 7f3116ffd700 20 librbd::io::ObjectRequest: 0x7f30fd29ca70 finish: rbd_data.020083acd075a3.0000000000000041 r=0
2023-11-03T20:18:17.213+0000 7f3116ffd700 20 librbd::Journal: 0x7f3108013c10 commit_io_event_extent: tid=132078, offset=272629760, length=4194304, r=0
2023-11-03T20:18:17.213+0000 7f3116ffd700 20 librbd::Journal: 0x7f3108013c10 complete_event: tid=132078 r=0
2023-11-03T20:18:17.213+0000 7f3116ffd700 20 librbd::cache::WriteAroundObjectDispatch: 0x7f30fc001100 handle_in_flight_io_complete: r=0, tid=134710
2023-11-03T20:18:17.213+0000 7f3116ffd700 20 librbd::io::SimpleSchedulerObjectDispatch: 0x7f30fc001fc0 dispatch_delayed_requests: object_no=65, 0 requests, dispatch_time=1970-01-01T00:00:00.000000+0000
2023-11-03T20:18:17.213+0000 7f3116ffd700 20 librbd::io::FlushTracker: 0x7f310801a670 finish_io: tid=134700, flush_tid=134700
2023-11-03T20:18:17.213+0000 7f3116ffd700 20 librbd::io::FlushTracker: 0x7f310801a670 finish_io: pending IOs: [134685,134687,134688,134689,134699], pending flushes={134695=0x55736ace1fb0}
2023-11-03T20:18:17.213+0000 7f31177fe700 20 librbd::object_map::UpdateRequest: 0x7f30fd2997d0 handle_update_object_map: r=0
2023-11-03T20:18:17.213+0000 7f31177fe700 20 librbd::object_map::UpdateRequest: 0x7f30fd2997d0 update_in_memory_object_map:
2023-11-03T20:18:17.213+0000 7f31177fe700 20 librbd::object_map::Request: 0x7f30fd2997d0 should_complete: r=0
2023-11-03T20:18:17.213+0000 7f31177fe700 20 librbd::ObjectMap: 0x55736a40dec0 handle_detained_aio_update: cell=0x7f30fc010e68, r=0
2023-11-03T20:18:17.213+0000 7f31177fe700 20 librbd::BlockGuard: 0x7f30fc0018b0 release: [block_start = 63, block_end = 64), pending_ops=0
2023-11-03T20:18:17.213+0000 7f31177fe700 20 librbd::io::ObjectRequest: 0x7f31092fbeb0 handle_post_write_object_map_update: rbd_data.020083acd075a3.000000000000003f r=0
2023-11-03T20:18:17.213+0000 7f31177fe700 20 librbd::io::ObjectRequest: 0x7f31092fbeb0 finish: rbd_data.020083acd075a3.000000000000003f r=0
2023-11-03T20:18:17.213+0000 7f31177fe700 20 librbd::Journal: 0x7f3108013c10 commit_io_event_extent: tid=132076, offset=264241152, length=4194304, r=0
2023-11-03T20:18:17.213+0000 7f31177fe700 20 librbd::Journal: 0x7f3108013c10 complete_event: tid=132076 r=0
2023-11-03T20:18:17.213+0000 7f31177fe700 20 librbd::cache::WriteAroundObjectDispatch: 0x7f30fc001100 handle_in_flight_io_complete: r=0, tid=134708
2023-11-03T20:18:17.213+0000 7f31177fe700 20 librbd::io::SimpleSchedulerObjectDispatch: 0x7f30fc001fc0 dispatch_delayed_requests: object_no=63, 0 requests, dispatch_time=1970-01-01T00:00:00.000000+0000
2023-11-03T20:18:17.213+0000 7f31177fe700 20 librbd::io::FlushTracker: 0x7f310801a670 finish_io: tid=134699, flush_tid=134699
2023-11-03T20:18:17.213+0000 7f31177fe700 20 librbd::io::FlushTracker: 0x7f310801a670 finish_io: pending IOs: [134685,134687,134688,134689], pending flushes={134695=0x55736ace1fb0}
2023-11-03T20:18:17.217+0000 7f3116ffd700 20 librbd::io::ObjectRequest: 0x7f310931b350 handle_write_object: rbd_data.020083acd075a3.0000000000000040 r=0
2023-11-03T20:18:17.217+0000 7f3116ffd700 20 librbd::io::ObjectRequest: 0x7f310931b350 finish: rbd_data.020083acd075a3.0000000000000040 r=0
2023-11-03T20:18:17.217+0000 7f3116ffd700 20 librbd::Journal: 0x7f3108013c10 commit_io_event_extent: tid=132063, offset=268845056, length=1040384, r=0
2023-11-03T20:18:17.217+0000 7f3116ffd700 20 librbd::Journal: 0x7f3108013c10 complete_event: tid=132063 r=0
2023-11-03T20:18:17.217+0000 7f3116ffd700 20 librbd::cache::WriteAroundObjectDispatch: 0x7f30fc001100 handle_in_flight_io_complete: r=0, tid=134693
2023-11-03T20:18:17.217+0000 7f3116ffd700 20 librbd::io::SimpleSchedulerObjectDispatch: 0x7f30fc001fc0 operator(): already dispatched
2023-11-03T20:18:17.217+0000 7f3116ffd700 20 librbd::io::FlushTracker: 0x7f310801a670 finish_io: tid=134685, flush_tid=134685
2023-11-03T20:18:17.217+0000 7f3116ffd700 20 librbd::io::FlushTracker: 0x7f310801a670 finish_io: pending IOs: [134687,134688,134689], pending flushes={134695=0x55736ace1fb0}
2023-11-03T20:18:17.221+0000 7f31177fe700 20 librbd::io::ObjectRequest: 0x7f31092f8680 handle_write_object: rbd_data.020083acd075a3.0000000000000040 r=0
2023-11-03T20:18:17.221+0000 7f31177fe700 20 librbd::io::ObjectRequest: 0x7f31092f8680 finish: rbd_data.020083acd075a3.0000000000000040 r=0
2023-11-03T20:18:17.221+0000 7f31177fe700 20 librbd::Journal: 0x7f3108013c10 commit_io_event_extent: tid=132062, offset=268435456, length=409600, r=0
2023-11-03T20:18:17.221+0000 7f31177fe700 20 librbd::Journal: 0x7f3108013c10 complete_event: tid=132062 r=0
2023-11-03T20:18:17.221+0000 7f31177fe700 20 librbd::cache::WriteAroundObjectDispatch: 0x7f30fc001100 handle_in_flight_io_complete: r=0, tid=134695
2023-11-03T20:18:17.221+0000 7f31177fe700 20 librbd::io::FlushTracker: 0x7f310801a670 finish_io: tid=134687, flush_tid=134687
2023-11-03T20:18:17.221+0000 7f31177fe700 20 librbd::io::FlushTracker: 0x7f310801a670 finish_io: pending IOs: [134688,134689], pending flushes={134695=0x55736ace1fb0}
2023-11-03T20:18:17.221+0000 7f3116ffd700 20 librbd::io::ObjectRequest: 0x7f3109322f30 handle_write_object: rbd_data.020083acd075a3.0000000000000040 r=0
2023-11-03T20:18:17.221+0000 7f3116ffd700 20 librbd::io::ObjectRequest: 0x7f3109322f30 finish: rbd_data.020083acd075a3.0000000000000040 r=0
2023-11-03T20:18:17.221+0000 7f3116ffd700 20 librbd::Journal: 0x7f3108013c10 commit_io_event_extent: tid=132064, offset=269885440, length=1040384, r=0
2023-11-03T20:18:17.221+0000 7f3116ffd700 20 librbd::Journal: 0x7f3108013c10 complete_event: tid=132064 r=0
2023-11-03T20:18:17.221+0000 7f3116ffd700 20 librbd::cache::WriteAroundObjectDispatch: 0x7f30fc001100 handle_in_flight_io_complete: r=0, tid=134696
2023-11-03T20:18:17.221+0000 7f3116ffd700 20 librbd::io::FlushTracker: 0x7f310801a670 finish_io: tid=134688, flush_tid=134688
2023-11-03T20:18:17.221+0000 7f3116ffd700 20 librbd::io::FlushTracker: 0x7f310801a670 finish_io: pending IOs: [134689], pending flushes={134695=0x55736ace1fb0}
2023-11-03T20:18:17.221+0000 7f3116ffd700 20 librbd::Journal: 0x7f3108013c10 commit_io_event_extent: tid=132065, offset=270925824, length=573440, r=0
2023-11-03T20:18:17.221+0000 7f3116ffd700 20 librbd::Journal: 0x7f3108013c10 complete_event: tid=132065 r=0
2023-11-03T20:18:17.221+0000 7f3116ffd700 20 librbd::cache::WriteAroundObjectDispatch: 0x7f30fc001100 handle_in_flight_io_complete: r=0, tid=134697
2023-11-03T20:18:17.221+0000 7f3116ffd700 20 librbd::cache::WriteAroundObjectDispatch: 0x7f30fc001100 unblock_overlapping_ios: queueing unblocked: tid=134709
2023-11-03T20:18:17.221+0000 7f3116ffd700 20 librbd::cache::WriteAroundObjectDispatch: 0x7f30fc001100 handle_in_flight_io_complete: dispatching IO: tid=134709
2023-11-03T20:18:17.221+0000 7f3116ffd700 20 librbd::io::Dispatcher: 0x55736a62bc60 send: dispatch_spec=0x55736a7ec9d0
2023-11-03T20:18:17.221+0000 7f3116ffd700 20 librbd::journal::ObjectDispatch: 0x7f30fc011cf0 discard: rbd_data.020083acd075a3.0000000000000040 65536~4128768
2023-11-03T20:18:17.221+0000 7f3116ffd700 20 librbd::journal::ObjectDispatch: 0x7f30fc011cf0 wait_or_flush_event: journal_tid=132078
2023-11-03T20:18:17.221+0000 7f3116ffd700 20 librbd::Journal: 0x7f3108013c10 wait_event: tid=132078, on_safe=0x55736a7ec9d0
    (1-1/1)