Bug #3551: mds: journaler hang - CephFS - Ceph

Actions

Copy link

Bug #3551

closed

mds: journaler hang

Added by Sage Weil over 11 years ago. Updated over 7 years ago.

Status:

Can't reproduce

Priority:

Low

Assignee:

Sage Weil

Category:

Target version:

% Done:

Source:

Development

Tags:

Backport:

Regression:

Severity:

Reviewed:

Affected Versions:

ceph-qa-suite:

Component(FS):

Labels (FS):

Pull request ID:

Crash signature (v1):

Crash signature (v2):

Description

2012-11-28 17:57:45.400472 7fe06dd95700  1 mds.0.journaler(ro) recover start
2012-11-28 17:57:45.400483 7fe06dd95700  1 mds.0.journaler(ro) read_head
2012-11-28 17:57:45.403376 7fe06dd95700  1 mds.0.journaler(ro) _finish_read_head loghead(trim 75497472, expire 75497801, write 205263990).  probing for end of log (from 205263990)...
2012-11-28 17:57:45.403385 7fe06dd95700  1 mds.0.journaler(ro) probing for end of the log
2012-11-28 17:57:45.406444 7fe06dd95700  1 mds.0.journaler(ro) _finish_probe_end write_pos = 205266937 (header had 205263990). recovered.
2012-11-28 17:57:45.408356 7fe0666f8700 10 mds.0.journaler(ro) _prefetch 41943040 requested_pos 75497801 < target 117440512 (117440841), prefetching 41942711
2012-11-28 17:57:45.408372 7fe0666f8700 10 mds.0.journaler(ro) _issue_read reading 75497801~41942711, read pointers 75497801/75497801/117440512
2012-11-28 17:57:45.410220 7fe0666f8700 10 mds.0.journaler(ro) wait_for_readable at 75497801 onreadable 0x7fe014009f90
2012-11-28 17:57:45.436303 7fe06dd95700 10 mds.0.journaler(ro) _finish_read got 79691776~4194304
2012-11-28 17:57:45.436317 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch gap of 4193975 from received_pos 75497801 to first prefetched buffer 79691776
2012-11-28 17:57:45.449918 7fe06dd95700 10 mds.0.journaler(ro) _finish_read got 92274688~4194304
2012-11-28 17:57:45.449930 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch gap of 4193975 from received_pos 75497801 to first prefetched buffer 79691776
2012-11-28 17:57:45.450258 7fe06dd95700 10 mds.0.journaler(ro) _finish_read got 96468992~4194304
2012-11-28 17:57:45.450265 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch gap of 4193975 from received_pos 75497801 to first prefetched buffer 79691776
2012-11-28 17:57:45.450703 7fe06dd95700 10 mds.0.journaler(ro) _finish_read got 83886080~4194304
2012-11-28 17:57:45.450709 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch gap of 4193975 from received_pos 75497801 to first prefetched buffer 79691776
2012-11-28 17:57:45.453033 7fe06dd95700 10 mds.0.journaler(ro) _finish_read got 109051904~4194304
2012-11-28 17:57:45.453039 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch gap of 4193975 from received_pos 75497801 to first prefetched buffer 79691776
2012-11-28 17:57:45.453991 7fe06dd95700 10 mds.0.journaler(ro) _finish_read got 100663296~4194304
2012-11-28 17:57:45.453996 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch gap of 4193975 from received_pos 75497801 to first prefetched buffer 79691776
2012-11-28 17:57:45.455937 7fe06dd95700 10 mds.0.journaler(ro) _finish_read got 113246208~4194304
2012-11-28 17:57:45.455942 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch gap of 4193975 from received_pos 75497801 to first prefetched buffer 79691776
2012-11-28 17:57:45.456031 7fe06dd95700 10 mds.0.journaler(ro) _finish_read got 104857600~4194304
2012-11-28 17:57:45.456034 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch gap of 4193975 from received_pos 75497801 to first prefetched buffer 79691776
2012-11-28 17:57:45.458912 7fe06dd95700 10 mds.0.journaler(ro) _finish_read got 88080384~4194304
2012-11-28 17:57:45.458916 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch gap of 4193975 from received_pos 75497801 to first prefetched buffer 79691776
2012-11-28 17:57:45.462905 7fe06dd95700 10 mds.0.journaler(ro) _finish_read got 75497801~4193975
2012-11-28 17:57:45.462909 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch 75497801~4193975
2012-11-28 17:57:45.462913 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch 79691776~4194304
2012-11-28 17:57:45.462916 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch 83886080~4194304
2012-11-28 17:57:45.462919 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch 88080384~4194304
2012-11-28 17:57:45.462922 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch 92274688~4194304
2012-11-28 17:57:45.462924 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch 96468992~4194304
2012-11-28 17:57:45.462927 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch 100663296~4194304
2012-11-28 17:57:45.462930 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch 104857600~4194304
2012-11-28 17:57:45.462932 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch 109051904~4194304
2012-11-28 17:57:45.462934 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch 113246208~4194304
2012-11-28 17:57:45.462937 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch read_buf now 75497801~41942711, read pointers 75497801/117440512/117440512
2012-11-28 17:57:45.462945 7fe06dd95700 10 mds.0.journaler(ro) _finish_read now readable (or at journal end)
2012-11-28 17:57:45.938132 7fe0666f8700 10 mds.0.journaler(ro) _prefetch 41943040 requested_pos 117440512 < target 121634816 (121635895), prefetching 4194304
2012-11-28 17:57:45.938138 7fe0666f8700 10 mds.0.journaler(ro) _issue_read reading 117440512~4194304, read pointers 79692855/117440512/121634816
2012-11-28 17:57:46.035067 7fe06dd95700 10 mds.0.journaler(ro) _finish_read got 117440512~4194304
2012-11-28 17:57:46.035078 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch 117440512~4194304
2012-11-28 17:57:46.035083 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch read_buf now 80573779~41061037, read pointers 80573779/121634816/121634816
2012-11-28 17:57:46.425855 7fe0666f8700 10 mds.0.journaler(ro) _prefetch 41943040 requested_pos 121634816 < target 125829120 (125829171), prefetching 4194304
2012-11-28 17:57:46.425861 7fe0666f8700 10 mds.0.journaler(ro) _issue_read reading 121634816~4194304, read pointers 83886131/121634816/125829120
2012-11-28 17:57:46.564119 7fe06dd95700 10 mds.0.journaler(ro) _finish_read got 121634816~4194304
2012-11-28 17:57:46.564128 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch 121634816~4194304
2012-11-28 17:57:46.564132 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch read_buf now 84982835~40846285, read pointers 84982835/125829120/125829120
2012-11-28 17:57:46.937757 7fe0666f8700 10 mds.0.journaler(ro) _prefetch 41943040 requested_pos 125829120 < target 130023424 (130023951), prefetching 4194304
2012-11-28 17:57:46.937763 7fe0666f8700 10 mds.0.journaler(ro) _issue_read reading 125829120~4194304, read pointers 88080911/125829120/130023424
2012-11-28 17:57:47.018132 7fe06dd95700 10 mds.0.journaler(ro) _finish_read got 125829120~4194304
2012-11-28 17:57:47.018140 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch 125829120~4194304
2012-11-28 17:57:47.018145 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch read_buf now 88730831~41292593, read pointers 88730831/130023424/130023424
2012-11-28 17:57:47.467309 7fe0666f8700 10 mds.0.journaler(ro) _prefetch 41943040 requested_pos 130023424 < target 134217728 (134217940), prefetching 4194304
2012-11-28 17:57:47.467315 7fe0666f8700 10 mds.0.journaler(ro) _issue_read reading 130023424~4194304, read pointers 92274900/130023424/134217728
2012-11-28 17:57:47.595139 7fe06dd95700 10 mds.0.journaler(ro) _finish_read got 130023424~4194304
2012-11-28 17:57:47.595149 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch 130023424~4194304
2012-11-28 17:57:47.595163 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch read_buf now 93351729~40865999, read pointers 93351729/134217728/134217728
2012-11-28 17:57:47.998985 7fe0666f8700 10 mds.0.journaler(ro) _prefetch 41943040 requested_pos 134217728 < target 138412032 (138413293), prefetching 4194304
2012-11-28 17:57:47.998991 7fe0666f8700 10 mds.0.journaler(ro) _issue_read reading 134217728~4194304, read pointers 96470253/134217728/138412032
2012-11-28 17:57:48.124144 7fe06dd95700 10 mds.0.journaler(ro) _finish_read got 134217728~4192939
2012-11-28 17:57:48.124154 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch 134217728~4192939
2012-11-28 17:57:48.124159 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch read_buf now 97538260~40872407, read pointers 97538260/138410667/138412032
2012-11-28 17:57:48.497603 7fe0666f8700 10 mds.0.journaler(ro) _prefetch 41943040 requested_pos 138412032 < target 142606336 (142606806), prefetching 4194304
2012-11-28 17:57:48.497609 7fe0666f8700 10 mds.0.journaler(ro) _issue_read reading 138412032~4194304, read pointers 100663766/138410667/142606336
2012-11-28 17:57:48.605142 7fe06dd95700 10 mds.0.journaler(ro) _finish_read got 138412032~4194304
2012-11-28 17:57:48.605153 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch gap of 1365 from received_pos 138410667 to first prefetched buffer 138412032
2012-11-28 17:57:48.982243 7fe0666f8700 10 mds.0.journaler(ro) _prefetch 41943040 requested_pos 142606336 < target 146800640 (146801016), prefetching 4194304
2012-11-28 17:57:48.982255 7fe0666f8700 10 mds.0.journaler(ro) _issue_read reading 142606336~4194304, read pointers 104857976/138410667/146800640
2012-11-28 17:57:49.031147 7fe06dd95700 10 mds.0.journaler(ro) _finish_read got 142606336~4194304
2012-11-28 17:57:49.031157 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch gap of 1365 from received_pos 138410667 to first prefetched buffer 138412032
2012-11-28 17:57:49.469730 7fe0666f8700 10 mds.0.journaler(ro) _prefetch 41943040 requested_pos 146800640 < target 150994944 (150995300), prefetching 4194304
2012-11-28 17:57:49.469735 7fe0666f8700 10 mds.0.journaler(ro) _issue_read reading 146800640~4194304, read pointers 109052260/138410667/150994944
2012-11-28 17:57:49.594144 7fe06dd95700 10 mds.0.journaler(ro) _finish_read got 146800640~4194304
2012-11-28 17:57:49.594154 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch gap of 1365 from received_pos 138410667 to first prefetched buffer 138412032
2012-11-28 17:57:49.907225 7fe0666f8700 10 mds.0.journaler(ro) _prefetch 41943040 requested_pos 150994944 < target 155189248 (155191656), prefetching 4194304
2012-11-28 17:57:49.907231 7fe0666f8700 10 mds.0.journaler(ro) _issue_read reading 150994944~4194304, read pointers 113248616/138410667/155189248
2012-11-28 17:57:50.149131 7fe06dd95700 10 mds.0.journaler(ro) _finish_read got 150994944~4194304
2012-11-28 17:57:50.149141 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch gap of 1365 from received_pos 138410667 to first prefetched buffer 138412032
2012-11-28 17:57:50.325024 7fe0666f8700 10 mds.0.journaler(ro) _prefetch 41943040 requested_pos 155189248 < target 159383552 (159383649), prefetching 4194304
2012-11-28 17:57:50.325029 7fe0666f8700 10 mds.0.journaler(ro) _issue_read reading 155189248~4194304, read pointers 117440609/138410667/159383552
2012-11-28 17:57:50.574205 7fe06dd95700 10 mds.0.journaler(ro) _finish_read got 155189248~4189689
2012-11-28 17:57:50.574215 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch gap of 1365 from received_pos 138410667 to first prefetched buffer 138412032
2012-11-28 17:57:50.740177 7fe0666f8700 10 mds.0.journaler(ro) _prefetch 41943040 requested_pos 159383552 < target 163577856 (163579288), prefetching 4194304
2012-11-28 17:57:50.740182 7fe0666f8700 10 mds.0.journaler(ro) _issue_read reading 159383552~4194304, read pointers 121636248/138410667/163577856
2012-11-28 17:57:50.806157 7fe06dd95700 10 mds.0.journaler(ro) _finish_read got 159383552~4194304
2012-11-28 17:57:50.806168 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch gap of 1365 from received_pos 138410667 to first prefetched buffer 138412032
2012-11-28 17:57:51.133177 7fe0666f8700 10 mds.0.journaler(ro) _prefetch 41943040 requested_pos 163577856 < target 167772160 (167772189), prefetching 4194304
2012-11-28 17:57:51.133182 7fe0666f8700 10 mds.0.journaler(ro) _issue_read reading 163577856~4194304, read pointers 125829149/138410667/167772160
2012-11-28 17:57:51.336130 7fe06dd95700 10 mds.0.journaler(ro) _finish_read got 163577856~4194304
2012-11-28 17:57:51.336137 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch gap of 1365 from received_pos 138410667 to first prefetched buffer 138412032
2012-11-28 17:57:51.390746 7fe0666f8700 10 mds.0.journaler(ro) _prefetch 41943040 requested_pos 167772160 < target 171966464 (171966934), prefetching 4194304
2012-11-28 17:57:51.390749 7fe0666f8700 10 mds.0.journaler(ro) _issue_read reading 167772160~4194304, read pointers 130023894/138410667/171966464
2012-11-28 17:57:51.603131 7fe06dd95700 10 mds.0.journaler(ro) _finish_read got 167772160~4194304
2012-11-28 17:57:51.603139 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch gap of 1365 from received_pos 138410667 to first prefetched buffer 138412032
2012-11-28 17:57:51.658770 7fe0666f8700 10 mds.0.journaler(ro) _prefetch 41943040 requested_pos 171966464 < target 176160768 (176162334), prefetching 4194304
2012-11-28 17:57:51.658774 7fe0666f8700 10 mds.0.journaler(ro) _issue_read reading 171966464~4194304, read pointers 134219294/138410667/176160768
2012-11-28 17:57:51.694126 7fe06dd95700 10 mds.0.journaler(ro) _finish_read got 171966464~4194304
2012-11-28 17:57:51.694132 7fe06dd95700 10 mds.0.journaler(ro) _assimilate_prefetch gap of 1365 from received_pos 138410667 to first prefetched buffer 138412032
2012-11-28 17:57:51.916386 7fe0666f8700 10 mds.0.journaler(ro) wait_for_readable at 138410667 onreadable 0x7fe0142fa910

...hang.