Project

General

Profile

Bug #2211

osd: entity_inst_t OSDMap::get_inst(int) const

Added by Wido den Hollander about 12 years ago. Updated almost 12 years ago.

Status:
Resolved
Priority:
Normal
Assignee:
Category:
OSD
Target version:
-
% Done:

0%

Spent time:
Source:
Development
Tags:
Backport:
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:
Crash signature (v1):
Crash signature (v2):

Description

While trying out the new heartbeat code I encountered this crash:

Core was generated by `/usr/bin/ceph-osd -i 8 -c /etc/ceph/ceph.conf'.
Program terminated with signal 6, Aborted.
#0  0x00007f28b4ff7f2b in raise () from /lib/x86_64-linux-gnu/libpthread.so.0
(gdb) bt
#0  0x00007f28b4ff7f2b in raise () from /lib/x86_64-linux-gnu/libpthread.so.0
#1  0x00000000006fb75d in reraise_fatal (signum=6) at global/signal_handler.cc:59
#2  handle_fatal_signal (signum=6) at global/signal_handler.cc:95
#3  <signal handler called>
#4  0x00007f28b35753a5 in raise () from /lib/x86_64-linux-gnu/libc.so.6
#5  0x00007f28b3578b0b in abort () from /lib/x86_64-linux-gnu/libc.so.6
#6  0x00007f28b3e33d7d in __gnu_cxx::__verbose_terminate_handler() () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#7  0x00007f28b3e31f26 in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#8  0x00007f28b3e31f53 in std::terminate() () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#9  0x00007f28b3e3204e in __cxa_throw () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#10 0x0000000000690540 in ceph::__ceph_assert_fail (assertion=0x804237 "is_up(osd)", file=0x811a8a "./osd/OSDMap.h", line=360, func=0x8156e0 "entity_inst_t OSDMap::get_inst(int) const") at common/assert.cc:75
#11 0x00000000005b210f in get_inst (this=<optimized out>, osd=<optimized out>) at ./osd/OSDMap.h:360
#12 get_inst (osd=0, this=<optimized out>) at osd/OSD.cc:2128
#13 OSD::send_failures (this=0x27eb000) at osd/OSD.cc:2137
#14 0x00000000005b5abb in OSD::do_mon_report (this=0x27eb000) at osd/OSD.cc:1867
#15 0x00000000005cb5c2 in OSD::tick (this=0x27eb000) at osd/OSD.cc:1736
#16 0x0000000000686ad9 in SafeTimer::timer_thread (this=0x27eb050) at common/Timer.cc:102
#17 0x00000000006876ad in SafeTimerThread::entry (this=<optimized out>) at common/Timer.cc:38
#18 0x00007f28b4fefefc in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#19 0x00007f28b362089d in clone () from /lib/x86_64-linux-gnu/libc.so.6
#20 0x0000000000000000 in ?? ()

The last log lines I got where:

2012-03-26 14:23:30.643006 7f28a730d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49f2]:0/24071 <== osd.4 [2a00:f10:11b:cef0:225:90ff:fe32:cf64]:6814/1652 1 ==== osd_ping(ping_reply e0 stamp 2012-03-26 14:23:30.640723) v2 ==== 47+0+0 (1642745581 0 0) 0x1a0b9c40 con 0x7e47dc0
2012-03-26 14:23:30.643237 7f28a730d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49f2]:0/24071 <== osd.7 [2a00:f10:11b:cef0:225:90ff:fe32:cf64]:6813/3697 1 ==== osd_ping(ping_reply e0 stamp 2012-03-26 14:23:30.640723) v2 ==== 47+0+0 (1642745581 0 0) 0x1a0b9540 con 0xa776140
2012-03-26 14:23:30.643389 7f28a730d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49f2]:0/24071 <== osd.12 [2a00:f10:11b:cef0:225:90ff:fe33:49b0]:6801/4725 1 ==== osd_ping(ping_reply e7983 stamp 2012-03-26 14:23:30.640723) v2 ==== 47+0+0 (2111163181 0 0) 0x1a0b9380 con 0xa776280
2012-03-26 14:23:30.643449 7f28a730d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49f2]:0/24071 <== osd.18 [2a00:f10:11b:cef0:225:90ff:fe33:49cc]:6803/14961 1 ==== osd_ping(ping_reply e0 stamp 2012-03-26 14:23:30.640723) v2 ==== 47+0+0 (1642745581 0 0) 0x1a0b9700 con 0xa776c80
2012-03-26 14:23:30.643530 7f28a730d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49f2]:0/24071 <== osd.22 [2a00:f10:11b:cef0:225:90ff:fe33:497c]:6804/22189 1 ==== osd_ping(ping_reply e7977 stamp 2012-03-26 14:23:30.640723) v2 ==== 47+0+0 (1810562802 0 0) 0x1a0b9e00 con 0xa776780
2012-03-26 14:23:30.643676 7f28a730d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49f2]:0/24071 <== osd.3 [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6807/5705 1 ==== osd_ping(ping_reply e7981 stamp 2012-03-26 14:23:30.640723) v2 ==== 47+0+0 (2358970935 0 0) 0x1a0b9a80 con 0x1a188780
2012-03-26 14:23:30.643887 7f28a730d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49f2]:0/24071 <== osd.6 [2a00:f10:11b:cef0:225:90ff:fe32:cf64]:6821/1802 1 ==== osd_ping(ping_reply e0 stamp 2012-03-26 14:23:30.640723) v2 ==== 47+0+0 (1642745581 0 0) 0x1a0b9000 con 0x2aac280
2012-03-26 14:23:30.643975 7f28a730d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49f2]:0/24071 <== osd.11 [2a00:f10:11b:cef0:225:90ff:fe33:49f2]:6812/23622 1 ==== osd_ping(ping_reply e7968 stamp 2012-03-26 14:23:30.640723) v2 ==== 47+0+0 (3628204292 0 0) 0x1a0b98c0 con 0x14d63a00
2012-03-26 14:23:30.644182 7f28a730d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49f2]:0/24071 <== osd.33 [2a00:f10:11b:cef0:225:90ff:fe33:498e]:6802/6908 1 ==== osd_ping(ping_reply e0 stamp 2012-03-26 14:23:30.640723) v2 ==== 47+0+0 (1642745581 0 0) 0x126b1380 con 0x102be500
2012-03-26 14:23:30.644397 7f28a730d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49f2]:0/24071 <== osd.32 [2a00:f10:11b:cef0:225:90ff:fe33:498e]:6813/6840 1 ==== osd_ping(ping_reply e7987 stamp 2012-03-26 14:23:30.640723) v2 ==== 47+0+0 (3260606612 0 0) 0x126b1000 con 0x1a188dc0
2012-03-26 14:23:30.644590 7f28a730d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49f2]:0/24071 <== osd.34 [2a00:f10:11b:cef0:225:90ff:fe33:498e]:6807/1953 1 ==== osd_ping(ping_reply e0 stamp 2012-03-26 14:23:30.640723) v2 ==== 47+0+0 (1642745581 0 0) 0x126b11c0 con 0xa776b40
2012-03-26 14:23:30.644806 7f28a730d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49f2]:0/24071 <== osd.16 [2a00:f10:11b:cef0:225:90ff:fe33:49cc]:6808/14817 1 ==== osd_ping(ping_reply e0 stamp 2012-03-26 14:23:30.640723) v2 ==== 47+0+0 (1642745581 0 0) 0x16cc1a80 con 0xa776a00
2012-03-26 14:23:30.645407 7f28a730d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49f2]:0/24071 <== osd.21 [2a00:f10:11b:cef0:225:90ff:fe33:497c]:6819/22110 1 ==== osd_ping(ping_reply e7971 stamp 2012-03-26 14:23:30.640723) v2 ==== 47+0+0 (1370202259 0 0) 0x16cc1e00 con 0xa776000
2012-03-26 14:23:30.823044 7f28a830f700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49f2]:6808/24071 <== mon.2 [2a00:f10:11b:cef0:230:48ff:fed3:b086]:6789/0 10 ==== mon_check_map_ack(handle=61 version=7987) v2 ==== 24+0+0 (719601101 0 0) 0x16cc1540 con 0x1a188a00
2012-03-26 14:23:30.823189 7f28a5b0a700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49f2]:6808/24071 --> [2a00:f10:11b:cef0:230:48ff:fed3:b086]:6789/0 -- osd_boot(osd.8 v7984) v2 -- ?+0 0x7a46000 con 0x1a188a00
./osd/OSDMap.h: In function 'entity_inst_t OSDMap::get_inst(int) const' thread 7f28afb1e700 time 2012-03-26 14:23:31.273426
./osd/OSDMap.h: 360: FAILED assert(is_up(osd))
 ceph version 0.44-59-g955b1cc (commit:955b1ccd0ddda378ed752a9f2731495b235209cf)
 1: (OSD::send_failures()+0x11f) [0x5b210f]
 2: (OSD::do_mon_report()+0x5b) [0x5b5abb]
 3: (OSD::tick()+0x842) [0x5cb5c2]
 4: (SafeTimer::timer_thread()+0x339) [0x686ad9]
 5: (SafeTimerThread::entry()+0xd) [0x6876ad]
 6: (()+0x7efc) [0x7f28b4fefefc]
 7: (clone()+0x6d) [0x7f28b362089d]
 ceph version 0.44-59-g955b1cc (commit:955b1ccd0ddda378ed752a9f2731495b235209cf)
 1: (OSD::send_failures()+0x11f) [0x5b210f]
 2: (OSD::do_mon_report()+0x5b) [0x5b5abb]
 3: (OSD::tick()+0x842) [0x5cb5c2]
 4: (SafeTimer::timer_thread()+0x339) [0x686ad9]
 5: (SafeTimerThread::entry()+0xd) [0x6876ad]
 6: (()+0x7efc) [0x7f28b4fefefc]
 7: (clone()+0x6d) [0x7f28b362089d]
*** Caught signal (Aborted) **
 in thread 7f28afb1e700
 ceph version 0.44-59-g955b1cc (commit:955b1ccd0ddda378ed752a9f2731495b235209cf)
 1: /usr/bin/ceph-osd() [0x6fb6e6]
 2: (()+0x10060) [0x7f28b4ff8060]
 3: (gsignal()+0x35) [0x7f28b35753a5]
 4: (abort()+0x17b) [0x7f28b3578b0b]
 5: (__gnu_cxx::__verbose_terminate_handler()+0x11d) [0x7f28b3e33d7d]
 6: (()+0xb9f26) [0x7f28b3e31f26]
 7: (()+0xb9f53) [0x7f28b3e31f53]
 8: (()+0xba04e) [0x7f28b3e3204e]
 9: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x200) [0x690540]
 10: (OSD::send_failures()+0x11f) [0x5b210f]
 11: (OSD::do_mon_report()+0x5b) [0x5b5abb]
 12: (OSD::tick()+0x842) [0x5cb5c2]
 13: (SafeTimer::timer_thread()+0x339) [0x686ad9]
 14: (SafeTimerThread::entry()+0xd) [0x6876ad]
 15: (()+0x7efc) [0x7f28b4fefefc]
 16: (clone()+0x6d) [0x7f28b362089d]

This happened in a state where my OSD's were still bouncing a bit since I restarted them fairly short after each other.

ceph_w.log View (434 KB) Wido den Hollander, 03/29/2012 01:40 AM

History

#1 Updated by Wido den Hollander about 12 years ago

Over night I saw 16 OSD's go down with the same backtrace.

All OSD's were running with debug ms/osd set to 1, this is what I got from osd.0:

2012-03-26 23:21:09.206131 7f17fc6d9700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 <== osd.37 [2a00:f10:11b:cef0:225:90ff:fe33:49a4]:0/14513 6 ==== osd_ping(ping e14311 stamp 2012-03-26 23:21:09.204589) v2 ==== 47+0+0 (878069784 0 0) 0x112d8000 con 0xa1a9500
2012-03-26 23:21:09.206242 7f17fc6d9700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 --> [2a00:f10:11b:cef0:225:90ff:fe33:49a4]:0/14513 -- osd_ping(ping_reply e14308 stamp 2012-03-26 23:21:09.204589) v2 -- ?+0 0x6e05380 con 0xa1a9500
2012-03-26 23:21:09.208329 7f17fc6d9700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 <== osd.11 [2a00:f10:11b:cef0:225:90ff:fe33:49f2]:0/10780 5 ==== osd_ping(ping e14311 stamp 2012-03-26 23:21:09.205842) v2 ==== 47+0+0 (3751942074 0 0) 0x9f921c0 con 0xa392dc0
2012-03-26 23:21:09.208408 7f17fc6d9700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 --> [2a00:f10:11b:cef0:225:90ff:fe33:49f2]:0/10780 -- osd_ping(ping_reply e14308 stamp 2012-03-26 23:21:09.205842) v2 -- ?+0 0x112d8000 con 0xa392dc0
2012-03-26 23:21:09.301140 7f17fc6d9700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 <== osd.36 [2a00:f10:11b:cef0:225:90ff:fe33:49a4]:0/14444 6 ==== osd_ping(ping e14311 stamp 2012-03-26 23:21:09.300391) v2 ==== 47+0+0 (3325284890 0 0) 0x960d380 con 0x56423c0
2012-03-26 23:21:09.301252 7f17fc6d9700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 --> [2a00:f10:11b:cef0:225:90ff:fe33:49a4]:0/14444 -- osd_ping(ping_reply e14308 stamp 2012-03-26 23:21:09.300391) v2 -- ?+0 0x9f921c0 con 0x56423c0
2012-03-26 23:21:09.400720 7f17fc6d9700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 <== osd.9 [2a00:f10:11b:cef0:225:90ff:fe33:49f2]:0/11340 4 ==== osd_ping(ping e14311 stamp 2012-03-26 23:21:09.401172) v2 ==== 47+0+0 (214029588 0 0) 0xcf4b380 con 0x47a9a00
2012-03-26 23:21:09.400805 7f17fc6d9700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 --> [2a00:f10:11b:cef0:225:90ff:fe33:49f2]:0/11340 -- osd_ping(ping_reply e14308 stamp 2012-03-26 23:21:09.401172) v2 -- ?+0 0x960d380 con 0x47a9a00
2012-03-26 23:21:09.426666 7f17fc6d9700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 <== osd.22 [2a00:f10:11b:cef0:225:90ff:fe33:497c]:0/5073 6 ==== osd_ping(ping e14311 stamp 2012-03-26 23:21:09.423825) v2 ==== 47+0+0 (3711105431 0 0) 0x6c0a540 con 0xb1f8280
2012-03-26 23:21:09.426777 7f17fc6d9700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 --> [2a00:f10:11b:cef0:225:90ff:fe33:497c]:0/5073 -- osd_ping(ping_reply e14308 stamp 2012-03-26 23:21:09.423825) v2 -- ?+0 0xcf4b380 con 0xb1f8280
2012-03-26 23:21:09.466123 7f17fc6d9700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 <== osd.17 [2a00:f10:11b:cef0:225:90ff:fe33:49cc]:0/19364 5 ==== osd_ping(ping e14311 stamp 2012-03-26 23:21:09.465833) v2 ==== 47+0+0 (1500428086 0 0) 0x1125f380 con 0x559cb40
2012-03-26 23:21:09.466237 7f17fc6d9700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 --> [2a00:f10:11b:cef0:225:90ff:fe33:49cc]:0/19364 -- osd_ping(ping_reply e14308 stamp 2012-03-26 23:21:09.465833) v2 -- ?+0 0x6c0a540 con 0x559cb40
2012-03-26 23:21:09.480115 7f17fc6d9700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 <== osd.24 [2a00:f10:11b:cef0:225:90ff:fe33:49ca]:0/26449 5 ==== osd_ping(ping e14311 stamp 2012-03-26 23:21:09.478417) v2 ==== 47+0+0 (255372651 0 0) 0x112d8380 con 0xa1a9640
2012-03-26 23:21:09.480190 7f17fc6d9700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 --> [2a00:f10:11b:cef0:225:90ff:fe33:49ca]:0/26449 -- osd_ping(ping_reply e14308 stamp 2012-03-26 23:21:09.478417) v2 -- ?+0 0x1125f380 con 0xa1a9640
2012-03-26 23:21:09.510881 7f17fc6d9700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 <== osd.34 [2a00:f10:11b:cef0:225:90ff:fe33:498e]:0/16800 5 ==== osd_ping(ping e14311 stamp 2012-03-26 23:21:09.511432) v2 ==== 47+0+0 (459034508 0 0) 0x3f11000 con 0x64b73c0
2012-03-26 23:21:09.510991 7f17fc6d9700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 --> [2a00:f10:11b:cef0:225:90ff:fe33:498e]:0/16800 -- osd_ping(ping_reply e14308 stamp 2012-03-26 23:21:09.511432) v2 -- ?+0 0x112d8380 con 0x64b73c0
2012-03-26 23:21:09.601951 7f17fc6d9700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 <== osd.21 [2a00:f10:11b:cef0:225:90ff:fe33:497c]:0/5004 6 ==== osd_ping(ping e14311 stamp 2012-03-26 23:21:09.599077) v2 ==== 47+0+0 (4249037645 0 0) 0x6c0a000 con 0xa392b40
2012-03-26 23:21:09.602052 7f17fc6d9700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 --> [2a00:f10:11b:cef0:225:90ff:fe33:497c]:0/5004 -- osd_ping(ping_reply e14308 stamp 2012-03-26 23:21:09.599077) v2 -- ?+0 0x3f11000 con 0xa392b40
2012-03-26 23:21:09.616828 7f17fc6d9700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 <== osd.38 [2a00:f10:11b:cef0:225:90ff:fe33:49a4]:0/14580 6 ==== osd_ping(ping e14311 stamp 2012-03-26 23:21:09.615566) v2 ==== 47+0+0 (373190033 0 0) 0x9656000 con 0xa1a9280
2012-03-26 23:21:09.616918 7f17fc6d9700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 --> [2a00:f10:11b:cef0:225:90ff:fe33:49a4]:0/14580 -- osd_ping(ping_reply e14308 stamp 2012-03-26 23:21:09.615566) v2 -- ?+0 0x6c0a000 con 0xa1a9280
2012-03-26 23:21:09.673339 7f17fc6d9700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 <== osd.23 [2a00:f10:11b:cef0:225:90ff:fe33:497c]:0/5164 6 ==== osd_ping(ping e14311 stamp 2012-03-26 23:21:09.668441) v2 ==== 47+0+0 (3176570333 0 0) 0xf46a000 con 0x6c9a3c0
2012-03-26 23:21:09.673422 7f17fc6d9700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 --> [2a00:f10:11b:cef0:225:90ff:fe33:497c]:0/5164 -- osd_ping(ping_reply e14308 stamp 2012-03-26 23:21:09.668441) v2 -- ?+0 0x9656000 con 0x6c9a3c0
2012-03-26 23:21:09.710195 7f17fc6d9700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 <== osd.10 [2a00:f10:11b:cef0:225:90ff:fe33:49f2]:0/10711 7 ==== osd_ping(ping e14312 stamp 2012-03-26 23:21:09.710115) v2 ==== 47+0+0 (573725144 0 0) 0xcdff540 con 0xb21a500
2012-03-26 23:21:09.710307 7f17fc6d9700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 --> [2a00:f10:11b:cef0:225:90ff:fe33:49f2]:0/10711 -- osd_ping(ping_reply e14308 stamp 2012-03-26 23:21:09.710115) v2 -- ?+0 0xf46a000 con 0xb21a500
2012-03-26 23:21:09.748136 7f17fc6d9700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 <== osd.19 [2a00:f10:11b:cef0:225:90ff:fe33:49cc]:0/19534 6 ==== osd_ping(ping e14311 stamp 2012-03-26 23:21:09.747438) v2 ==== 47+0+0 (2773366083 0 0) 0xa0dd700 con 0x5be9640
2012-03-26 23:21:09.748223 7f17fc6d9700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 --> [2a00:f10:11b:cef0:225:90ff:fe33:49cc]:0/19534 -- osd_ping(ping_reply e14308 stamp 2012-03-26 23:21:09.747438) v2 -- ?+0 0xcdff540 con 0x5be9640
2012-03-26 23:21:09.754252 7f17fc6d9700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 <== osd.26 [2a00:f10:11b:cef0:225:90ff:fe33:49ca]:0/26587 6 ==== osd_ping(ping e14311 stamp 2012-03-26 23:21:09.751098) v2 ==== 47+0+0 (2245835529 0 0) 0x95d4000 con 0x64b7a00
2012-03-26 23:21:09.754335 7f17fc6d9700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 --> [2a00:f10:11b:cef0:225:90ff:fe33:49ca]:0/26587 -- osd_ping(ping_reply e14308 stamp 2012-03-26 23:21:09.751098) v2 -- ?+0 0xa0dd700 con 0x64b7a00
2012-03-26 23:21:09.821126 7f17fc6d9700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 <== osd.11 [2a00:f10:11b:cef0:225:90ff:fe33:49f2]:0/10780 6 ==== osd_ping(ping e14311 stamp 2012-03-26 23:21:09.818625) v2 ==== 47+0+0 (1415364108 0 0) 0x9f92000 con 0xa392dc0
2012-03-26 23:21:09.821214 7f17fc6d9700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 --> [2a00:f10:11b:cef0:225:90ff:fe33:49f2]:0/10780 -- osd_ping(ping_reply e14308 stamp 2012-03-26 23:21:09.818625) v2 -- ?+0 0x95d4000 con 0xa392dc0
2012-03-26 23:21:09.822468 7f17fc6d9700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 <== osd.14 [2a00:f10:11b:cef0:225:90ff:fe33:49b0]:0/12780 6 ==== osd_ping(ping e0 stamp 2012-03-26 23:21:09.818501) v2 ==== 47+0+0 (2236656815 0 0) 0x7735700 con 0xb21ab40
2012-03-26 23:21:09.822548 7f17fc6d9700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 --> [2a00:f10:11b:cef0:225:90ff:fe33:49b0]:0/12780 -- osd_ping(ping_reply e14308 stamp 2012-03-26 23:21:09.818501) v2 -- ?+0 0x9f92000 con 0xb21ab40
2012-03-26 23:21:09.825176 7f17fc6d9700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 <== osd.13 [2a00:f10:11b:cef0:225:90ff:fe33:49b0]:0/12710 6 ==== osd_ping(ping e14312 stamp 2012-03-26 23:21:09.821674) v2 ==== 47+0+0 (3883391871 0 0) 0xd5be8c0 con 0x559cc80
2012-03-26 23:21:09.825279 7f17fc6d9700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 --> [2a00:f10:11b:cef0:225:90ff:fe33:49b0]:0/12710 -- osd_ping(ping_reply e14308 stamp 2012-03-26 23:21:09.821674) v2 -- ?+0 0x7735700 con 0x559cc80
2012-03-26 23:21:09.859258 7f17fc6d9700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 <== osd.18 [2a00:f10:11b:cef0:225:90ff:fe33:49cc]:0/19441 5 ==== osd_ping(ping e0 stamp 2012-03-26 23:21:09.856443) v2 ==== 47+0+0 (2077744200 0 0) 0x6c0a8c0 con 0x5149dc0
2012-03-26 23:21:09.859371 7f17fc6d9700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 --> [2a00:f10:11b:cef0:225:90ff:fe33:49cc]:0/19441 -- osd_ping(ping_reply e14308 stamp 2012-03-26 23:21:09.856443) v2 -- ?+0 0xd5be8c0 con 0x5149dc0
2012-03-26 23:21:09.861541 7f17fc6d9700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 <== osd.35 [2a00:f10:11b:cef0:225:90ff:fe33:498e]:0/16910 5 ==== osd_ping(ping e0 stamp 2012-03-26 23:21:09.858908) v2 ==== 47+0+0 (2368250613 0 0) 0x611c540 con 0x561d780
2012-03-26 23:21:09.861696 7f17fc6d9700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 --> [2a00:f10:11b:cef0:225:90ff:fe33:498e]:0/16910 -- osd_ping(ping_reply e14308 stamp 2012-03-26 23:21:09.858908) v2 -- ?+0 0x6c0a8c0 con 0x561d780
2012-03-26 23:21:09.862121 7f17ec113700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6812/23820 >> :/0 pipe(0x10ca3c80 sd=69 pgs=0 cs=0 l=0).accept sd=69
2012-03-26 23:21:09.869066 7f17de83b700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 >> :/0 pipe(0xa1bd280 sd=72 pgs=0 cs=0 l=0).accept sd=72
2012-03-26 23:21:09.906449 7f17e9aed700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6813/23820 >> :/0 pipe(0xa1bd780 sd=111 pgs=0 cs=0 l=0).accept sd=111
2012-03-26 23:21:09.944703 7f18056eb700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6802/23820 --> [2a00:f10:11b:cef0:230:48ff:fed3:b086]:6789/0 -- osd_pgtemp(e14308 {0.8ac=[0,23,22],1.8ab=[0,23,22],2.8aa=[0,23,22]} v14308) v1 -- ?+0 0x3c0b800 con 0x9edca00
./osd/OSDMap.h: In function 'entity_inst_t OSDMap::get_inst(int) const' thread 7f18056eb700 time 2012-03-26 23:21:09.944852
./osd/OSDMap.h: 360: FAILED assert(is_up(osd))
 ceph version 0.44-70-gcb23008 (commit:cb2300836ea20d302c050f6a05a327c750e5b231)
 1: (OSD::send_failures()+0x11f) [0x5b223f]
 2: (OSD::do_mon_report()+0x5b) [0x5b5b2b]
 3: (OSD::tick()+0x83a) [0x5cb62a]
 4: (SafeTimer::timer_thread()+0x339) [0x6864c9]
 5: (SafeTimerThread::entry()+0xd) [0x68709d]
 6: (()+0x7efc) [0x7f180abbcefc]
 7: (clone()+0x6d) [0x7f18091ed89d]
 ceph version 0.44-70-gcb23008 (commit:cb2300836ea20d302c050f6a05a327c750e5b231)
 1: (OSD::send_failures()+0x11f) [0x5b223f]
 2: (OSD::do_mon_report()+0x5b) [0x5b5b2b]
 3: (OSD::tick()+0x83a) [0x5cb62a]
 4: (SafeTimer::timer_thread()+0x339) [0x6864c9]
 5: (SafeTimerThread::entry()+0xd) [0x68709d]
 6: (()+0x7efc) [0x7f180abbcefc]
 7: (clone()+0x6d) [0x7f18091ed89d]
*** Caught signal (Aborted) **
 in thread 7f18056eb700
 ceph version 0.44-70-gcb23008 (commit:cb2300836ea20d302c050f6a05a327c750e5b231)
 1: /usr/bin/ceph-osd() [0x6fb7e6]
 2: (()+0x10060) [0x7f180abc5060]
 3: (gsignal()+0x35) [0x7f18091423a5]
 4: (abort()+0x17b) [0x7f1809145b0b]
 5: (__gnu_cxx::__verbose_terminate_handler()+0x11d) [0x7f1809a00d7d]
 6: (()+0xb9f26) [0x7f18099fef26]
 7: (()+0xb9f53) [0x7f18099fef53]
 8: (()+0xba04e) [0x7f18099ff04e]
 9: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x200) [0x68ff30]
 10: (OSD::send_failures()+0x11f) [0x5b223f]
 11: (OSD::do_mon_report()+0x5b) [0x5b5b2b]
 12: (OSD::tick()+0x83a) [0x5cb62a]
 13: (SafeTimer::timer_thread()+0x339) [0x6864c9]
 14: (SafeTimerThread::entry()+0xd) [0x68709d]
 15: (()+0x7efc) [0x7f180abbcefc]
 16: (clone()+0x6d) [0x7f18091ed89d]

I also grabbed the logs from osd.1, that shows:

2012-03-27 01:40:05.652751 7f03ef119700 osd.1 22256 heartbeat allocating ping for osd.26
2012-03-27 01:40:05.652791 7f03ef119700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/23890 send_message dropped message osd_ping(ping e0 stamp 2012-03-27 01:40:05.652141) v2 because of no pipe on con 0x22014c80
2012-03-27 01:40:05.652814 7f03ef119700 osd.1 22256 heartbeat allocating ping for osd.36
2012-03-27 01:40:05.652852 7f03ef119700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/23890 send_message dropped message osd_ping(ping e0 stamp 2012-03-27 01:40:05.652141) v2 because of no pipe on con 0x22014780
2012-03-27 01:40:05.652874 7f03ef119700 osd.1 22256 heartbeat allocating ping for osd.37
2012-03-27 01:40:05.652911 7f03ef119700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/23890 send_message dropped message osd_ping(ping e0 stamp 2012-03-27 01:40:05.652141) v2 because of no pipe on con 0x1100a3c0
2012-03-27 01:40:05.652933 7f03ef119700 osd.1 22256 heartbeat allocating ping for osd.38
2012-03-27 01:40:05.652971 7f03ef119700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/23890 send_message dropped message osd_ping(ping e0 stamp 2012-03-27 01:40:05.652141) v2 because of no pipe on con 0x13eb88c0
2012-03-27 01:40:05.652993 7f03ef119700 osd.1 22256 heartbeat allocating ping for osd.39
2012-03-27 01:40:05.653030 7f03ef119700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/23890 send_message dropped message osd_ping(ping e0 stamp 2012-03-27 01:40:05.652141) v2 because of no pipe on con 0x32c5640
2012-03-27 01:40:05.653052 7f03ef119700 osd.1 22256 heartbeat no map_lock, no check
2012-03-27 01:40:05.653075 7f03ef119700 osd.1 22256 heartbeat done
2012-03-27 01:40:05.653112 7f03ef119700 osd.1 22256 heartbeat_entry sleeping for 1.4
2012-03-27 01:40:05.653753 7f03f3a23700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/23890 <== osd.24 [2a00:f10:11b:cef0:225:90ff:fe33:49ca]:6810/26449 30 ==== osd_ping(ping_reply e0 stamp 2012-03-27 01:40:05.652141) v2 ==== 47+0+0 (2571380673 0 0) 0x19983e00 con 0x2633d3c0
2012-03-27 01:40:06.361972 7f03f4a25700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6809/23890 --> [2a00:f10:11a:409::1]:6789/0 -- mon_get_version(what=osdmap handle=712) v1 -- ?+0 0x370c81c0 con 0x8b55000
2012-03-27 01:40:06.387678 7f03f4a25700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6809/23890 <== mon.1 [2a00:f10:11a:409::1]:6789/0 4 ==== mon_subscribe_ack(300s) v1 ==== 20+0+0 (4083322184 0 0) 0x52ef540 con 0x8b55000
2012-03-27 01:40:06.387809 7f03fc234700 osd.1 22256 heartbeat_check: no reply from osd.9 since 2012-03-27 01:39:41.214484 (cutoff 2012-03-27 01:39:46.387732)
2012-03-27 01:40:06.387887 7f03fc234700 osd.1 22256 heartbeat_check: no reply from osd.17 since 2012-03-27 01:39:41.214484 (cutoff 2012-03-27 01:39:46.387732)
2012-03-27 01:40:06.387928 7f03fc234700 osd.1 22256 heartbeat_check: no reply from osd.36 since 2012-03-27 01:39:41.214484 (cutoff 2012-03-27 01:39:46.387732)
2012-03-27 01:40:06.387967 7f03fc234700 osd.1 22256 heartbeat_check: no reply from osd.39 since 2012-03-27 01:39:45.521080 (cutoff 2012-03-27 01:39:46.387732)
2012-03-27 01:40:06.388047 7f03f4a25700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6809/23890 <== mon.1 [2a00:f10:11a:409::1]:6789/0 5 ==== osd_map(22189..22256 src has 10684..22256) v3 ==== 21104+0+0 (3336195930 0 0) 0x30486400 con 0x8b55000
2012-03-27 01:40:06.388135 7f03fc234700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6809/23890 --> [2a00:f10:11a:409::1]:6789/0 -- osd_failure(osd.9 [2a00:f10:11b:cef0:225:90ff:fe33:49f2]:6809/11340 e22256 v22256) v2 -- ?+0 0x1e93ab40 con 0x8b55000
2012-03-27 01:40:06.388202 7f03fc234700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6809/23890 --> [2a00:f10:11a:409::1]:6789/0 -- osd_failure(osd.17 [2a00:f10:11b:cef0:225:90ff:fe33:49cc]:6803/19364 e22256 v22256) v2 -- ?+0 0x1e93a6c0 con 0x8b55000
2012-03-27 01:40:06.388256 7f03fc234700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6809/23890 --> [2a00:f10:11a:409::1]:6789/0 -- osd_failure(osd.36 [2a00:f10:11b:cef0:225:90ff:fe33:49a4]:6800/14444 e22256 v22256) v2 -- ?+0 0x856cd80 con 0x8b55000
./osd/OSDMap.h: In function 'entity_inst_t OSDMap::get_inst(int) const' thread 7f03fc234700 time 2012-03-27 01:40:06.394094
./osd/OSDMap.h: 360: FAILED assert(is_up(osd))
 ceph version 0.44-70-gcb23008 (commit:cb2300836ea20d302c050f6a05a327c750e5b231)
 1: (OSD::send_failures()+0x11f) [0x5b223f]
 2: (OSD::do_mon_report()+0x5b) [0x5b5b2b]
 3: (OSD::tick()+0x83a) [0x5cb62a]
 4: (SafeTimer::timer_thread()+0x339) [0x6864c9]
 5: (SafeTimerThread::entry()+0xd) [0x68709d]
 6: (()+0x7efc) [0x7f0401705efc]
 7: (clone()+0x6d) [0x7f03ffd3689d]
 ceph version 0.44-70-gcb23008 (commit:cb2300836ea20d302c050f6a05a327c750e5b231)
 1: (OSD::send_failures()+0x11f) [0x5b223f]
 2: (OSD::do_mon_report()+0x5b) [0x5b5b2b]
 3: (OSD::tick()+0x83a) [0x5cb62a]
 4: (SafeTimer::timer_thread()+0x339) [0x6864c9]
 5: (SafeTimerThread::entry()+0xd) [0x68709d]
 6: (()+0x7efc) [0x7f0401705efc]
 7: (clone()+0x6d) [0x7f03ffd3689d]
*** Caught signal (Aborted) **
 in thread 7f03fc234700
 ceph version 0.44-70-gcb23008 (commit:cb2300836ea20d302c050f6a05a327c750e5b231)
 1: /usr/bin/ceph-osd() [0x6fb7e6]
 2: (()+0x10060) [0x7f040170e060]
 3: (gsignal()+0x35) [0x7f03ffc8b3a5]
 4: (abort()+0x17b) [0x7f03ffc8eb0b]
 5: (__gnu_cxx::__verbose_terminate_handler()+0x11d) [0x7f0400549d7d]
 6: (()+0xb9f26) [0x7f0400547f26]
 7: (()+0xb9f53) [0x7f0400547f53]
 8: (()+0xba04e) [0x7f040054804e]
 9: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x200) [0x68ff30]
 10: (OSD::send_failures()+0x11f) [0x5b223f]
 11: (OSD::do_mon_report()+0x5b) [0x5b5b2b]
 12: (OSD::tick()+0x83a) [0x5cb62a]
 13: (SafeTimer::timer_thread()+0x339) [0x6864c9]
 14: (SafeTimerThread::entry()+0xd) [0x68709d]
 15: (()+0x7efc) [0x7f0401705efc]
 16: (clone()+0x6d) [0x7f03ffd3689d]

#2 Updated by Sage Weil about 12 years ago

  • Status changed from New to 12
  • Assignee set to Sage Weil

Can you attach the full osd.1 log?

#3 Updated by Wido den Hollander about 12 years ago

It's quite large (222MB), so I uploaded the file, available at: http://logger.ceph.widodh.nl/ceph/osd.1.log_27-03-2012.gz

#4 Updated by Sage Weil almost 12 years ago

Ah, I see the bug now. Pushed a fix to wip-osd-hb, thanks!

Let us know if this behaves for you.. if so I'll pull it in for v0.45!

#5 Updated by Wido den Hollander almost 12 years ago

I just installted the code on my cluster and things do not seem to behave yet.

The cluster is still jumping around, they keep marking each other down and OSD's seem to be in the boot state continuously.

Stuff like:

2012-03-29 10:36:27.639421   log 2012-03-29 10:36:22.298486 osd.18 [2a00:f10:11b:cef0:225:90ff:fe33:49cc]:6822/14149 25 : [WRN] map e29419 wrongly marked me down or wrong addr
2012-03-29 10:36:27.639421   log 2012-03-29 10:36:23.583113 osd.4 [2a00:f10:11b:cef0:225:90ff:fe32:cf64]:6812/19229 37 : [WRN] map e29420 wrongly marked me down or wrong addr
2012-03-29 10:36:27.639421   log 2012-03-29 10:36:27.368445 mon.0 [2a00:f10:11a:408::1]:6789/0 130541 : [INF] osd.32 [2a00:f10:11b:cef0:225:90ff:fe33:498e]:6816/14094 boot
2012-03-29 10:36:27.639421   log 2012-03-29 10:36:27.374950 mon.0 [2a00:f10:11a:408::1]:6789/0 130542 : [INF] osd.5 [2a00:f10:11b:cef0:225:90ff:fe32:cf64]:6815/19456 boot

It seems to be that OSD's somethings mark a bunch of other OSD's as down:

2012-03-29 10:36:25.737265   log 2012-03-29 10:36:25.050203 mon.0 [2a00:f10:11a:408::1]:6789/0 130533 : [INF] osd.5 [2a00:f10:11b:cef0:225:90ff:fe32:cf64]:6815/19456 failed (by osd.28 [2a00:f10:11b:cef0:225:90ff:fe33:499c]:6814/13959)
2012-03-29 10:36:25.737265   log 2012-03-29 10:36:25.051016 mon.0 [2a00:f10:11a:408::1]:6789/0 130534 : [INF] osd.9 [2a00:f10:11b:cef0:225:90ff:fe33:49f2]:6822/16809 failed (by osd.28 [2a00:f10:11b:cef0:225:90ff:fe33:499c]:6814/13959)
2012-03-29 10:36:25.737265   log 2012-03-29 10:36:25.051399 mon.0 [2a00:f10:11a:408::1]:6789/0 130535 : [INF] osd.11 [2a00:f10:11b:cef0:225:90ff:fe33:49f2]:6816/15559 failed (by osd.28 [2a00:f10:11b:cef0:225:90ff:fe33:499c]:6814/13959)
2012-03-29 10:36:25.737265   log 2012-03-29 10:36:25.051775 mon.0 [2a00:f10:11a:408::1]:6789/0 130536 : [INF] osd.32 [2a00:f10:11b:cef0:225:90ff:fe33:498e]:6816/14094 failed (by osd.28 [2a00:f10:11b:cef0:225:90ff:fe33:499c]:6814/13959)

To verify they are all running the same code:

root@monitor:~# dsh -g osd "ceph-osd -v" 
ceph version 0.44-71-ge191aca (commit:e191acace4424978d096e5304deec3c5f853726d)
ceph version 0.44-71-ge191aca (commit:e191acace4424978d096e5304deec3c5f853726d)
ceph version 0.44-71-ge191aca (commit:e191acace4424978d096e5304deec3c5f853726d)
ceph version 0.44-71-ge191aca (commit:e191acace4424978d096e5304deec3c5f853726d)
ceph version 0.44-71-ge191aca (commit:e191acace4424978d096e5304deec3c5f853726d)
ceph version 0.44-71-ge191aca (commit:e191acace4424978d096e5304deec3c5f853726d)
ceph version 0.44-71-ge191aca (commit:e191acace4424978d096e5304deec3c5f853726d)
ceph version 0.44-71-ge191aca (commit:e191acace4424978d096e5304deec3c5f853726d)
ceph version 0.44-71-ge191aca (commit:e191acace4424978d096e5304deec3c5f853726d)
ceph version 0.44-71-ge191aca (commit:e191acace4424978d096e5304deec3c5f853726d)
root@monitor:~#

The load on the machines is however very high:

root@monitor:~# dsh -g osd uptime
 10:39:33 up 1 day, 18:35,  1 user,  load average: 5.40, 6.82, 5.69
 10:39:34 up 1 day, 18:17,  1 user,  load average: 7.04, 7.45, 5.90
 10:39:35 up 1 day, 15:58,  1 user,  load average: 6.31, 6.39, 4.93
 10:39:36 up 1 day, 15:50,  1 user,  load average: 6.15, 6.30, 4.96
 10:39:37 up 1 day, 15:47,  1 user,  load average: 5.46, 5.84, 4.55
 10:39:38 up 1 day, 15:44,  1 user,  load average: 7.84, 8.78, 6.87
 10:39:38 up 1 day, 15:39,  1 user,  load average: 10.46, 10.17, 7.90
 10:39:39 up 1 day, 15:35,  1 user,  load average: 7.40, 8.24, 6.48
 10:39:40 up 1 day, 15:31,  1 user,  load average: 5.77, 5.99, 4.80
 10:39:41 up 1 day, 15:27,  1 user,  load average: 7.38, 6.36, 4.75
root@monitor:~#

That could be the root cause of this, something might be keeping them busy. I think it's the high rate of logging I'm seeing (heartbeat stuff) which eats CPU and causes them to loose heartbeat messages.

I'll try to see if I can change the heartbeat interval to calm stuff down.

#6 Updated by Wido den Hollander almost 12 years ago

I reverted the extra debugging for the heartbeat stuff, but that didn't seem to consume all the CPU time.

The load on all the machines is still very high, 6 ~ 10 on all nodes.

This could ofcourse be a result of the limited CPU power of the Atom, but since stuff was running on the Atom's, I'm trying to figure out where the CPU time is going.

vmstat shows it's not I/O wait btw.

I started looking in the logs of osd.0 and found:

2012-03-29 11:51:44.498523 7f652df2d700 osd.0 33566 note_down_osd osd.1
2012-03-29 11:51:44.498613 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6899/18540 mark_down [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6857/18771 -- pipe dne
2012-03-29 11:51:44.498654 7f652df2d700 osd.0 33566 note_down_osd osd.2
2012-03-29 11:51:44.498709 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6899/18540 mark_down [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6861/19114 -- pipe dne
2012-03-29 11:51:44.498746 7f652df2d700 osd.0 33566 note_down_osd osd.4
2012-03-29 11:51:44.498803 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6899/18540 mark_down [2a00:f10:11b:cef0:225:90ff:fe32:cf64]:6829/16326 -- 0x28b8a00
2012-03-29 11:51:44.498930 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/18540 mark_down 0x2ce3280 -- 0x2d04280
2012-03-29 11:51:44.499020 7f652df2d700 osd.0 33566 note_down_osd osd.5
2012-03-29 11:51:44.499085 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6899/18540 mark_down [2a00:f10:11b:cef0:225:90ff:fe32:cf64]:6831/16552 -- 0x31d8500
2012-03-29 11:51:44.499163 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/18540 mark_down 0x2f51a00 -- pipe dne
2012-03-29 11:51:44.499204 7f652df2d700 osd.0 33566 note_down_osd osd.6
2012-03-29 11:51:44.499261 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6899/18540 mark_down [2a00:f10:11b:cef0:225:90ff:fe32:cf64]:6827/16791 -- 0x3389000
2012-03-29 11:51:44.499363 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/18540 mark_down 0x2671000 -- 0x3a8ca00
2012-03-29 11:51:44.499453 7f652df2d700 osd.0 33566 note_down_osd osd.7
2012-03-29 11:51:44.499514 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6899/18540 mark_down [2a00:f10:11b:cef0:225:90ff:fe32:cf64]:6888/17024 -- 0x2880280
2012-03-29 11:51:44.499610 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/18540 mark_down 0x2bc5280 -- 0x35c1500
2012-03-29 11:51:44.499696 7f652df2d700 osd.0 33566 note_down_osd osd.9
2012-03-29 11:51:44.499757 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6899/18540 mark_down [2a00:f10:11b:cef0:225:90ff:fe33:49f2]:6828/6328 -- 0x31fa000
2012-03-29 11:51:44.501169 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/18540 mark_down 0x34fb640 -- pipe dne
2012-03-29 11:51:44.501297 7f652df2d700 osd.0 33566 note_down_osd osd.10
2012-03-29 11:51:44.501367 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6899/18540 mark_down [2a00:f10:11b:cef0:225:90ff:fe33:49f2]:6808/5116 -- 0x2f26780
2012-03-29 11:51:44.501466 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/18540 mark_down 0x2dae500 -- 0x30a8a00
2012-03-29 11:51:44.501637 7f652df2d700 osd.0 33566 note_down_osd osd.12
2012-03-29 11:51:44.501718 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6899/18540 mark_down [2a00:f10:11b:cef0:225:90ff:fe33:49b0]:6860/1675 -- 0x3180a00
2012-03-29 11:51:44.501796 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/18540 mark_down 0x2f1cc80 -- pipe dne
2012-03-29 11:51:44.501841 7f652df2d700 osd.0 33566 note_down_osd osd.13
2012-03-29 11:51:44.501897 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6899/18540 mark_down [2a00:f10:11b:cef0:225:90ff:fe33:49b0]:6858/1971 -- 0x324ac80
2012-03-29 11:51:44.503468 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/18540 mark_down 0x339fb40 -- pipe dne
2012-03-29 11:51:44.503633 7f652df2d700 osd.0 33566 note_down_osd osd.14
2012-03-29 11:51:44.503710 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6899/18540 mark_down [2a00:f10:11b:cef0:225:90ff:fe33:49b0]:6862/2231 -- 0x339cc80
2012-03-29 11:51:44.503794 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/18540 mark_down 0x2dae640 -- pipe dne
2012-03-29 11:51:44.503839 7f652df2d700 osd.0 33566 note_down_osd osd.15
2012-03-29 11:51:44.503899 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6899/18540 mark_down [2a00:f10:11b:cef0:225:90ff:fe33:49b0]:6896/2820 -- 0x339ca00
2012-03-29 11:51:44.503973 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/18540 mark_down 0x2b19000 -- pipe dne
2012-03-29 11:51:44.504015 7f652df2d700 osd.0 33566 note_down_osd osd.16
2012-03-29 11:51:44.504075 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6899/18540 mark_down [2a00:f10:11b:cef0:225:90ff:fe33:49cc]:6835/32740 -- 0x3a8c000
2012-03-29 11:51:44.504444 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/18540 mark_down 0x32c9640 -- 0x3975280
2012-03-29 11:51:44.504968 7f652df2d700 osd.0 33566 note_down_osd osd.18
2012-03-29 11:51:44.505998 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6899/18540 mark_down [2a00:f10:11b:cef0:225:90ff:fe33:49cc]:6837/767 -- 0x3d0c280
2012-03-29 11:51:44.506468 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/18540 mark_down 0x2f1c3c0 -- 0x2353780
2012-03-29 11:51:44.506787 7f652df2d700 osd.0 33566 note_down_osd osd.24
2012-03-29 11:51:44.506894 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6899/18540 mark_down [2a00:f10:11b:cef0:225:90ff:fe33:49ca]:6800/16986 -- 0x2262780
2012-03-29 11:51:44.507401 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/18540 mark_down 0x2f1c140 -- 0x3975000
2012-03-29 11:51:44.507744 7f652df2d700 osd.0 33566 note_down_osd osd.26
2012-03-29 11:51:44.507857 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6899/18540 mark_down [2a00:f10:11b:cef0:225:90ff:fe33:49ca]:6853/17888 -- 0x3798000
2012-03-29 11:51:44.508138 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/18540 mark_down 0x2bc5a00 -- 0x36f8780
2012-03-29 11:51:44.508763 7f652df2d700 osd.0 33566 note_down_osd osd.28
2012-03-29 11:51:44.508896 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6899/18540 mark_down [2a00:f10:11b:cef0:225:90ff:fe33:499c]:6826/11780 -- 0x3769c80
2012-03-29 11:51:44.509565 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/18540 mark_down 0x2f51dc0 -- 0x3249500
2012-03-29 11:51:44.510203 7f652df2d700 osd.0 33566 note_down_osd osd.29
2012-03-29 11:51:44.510691 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6899/18540 mark_down [2a00:f10:11b:cef0:225:90ff:fe33:499c]:6822/12262 -- 0x3c01c80
2012-03-29 11:51:44.510843 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/18540 mark_down 0x2f51500 -- 0x3e9fc80
2012-03-29 11:51:44.510946 7f652df2d700 osd.0 33566 note_down_osd osd.30
2012-03-29 11:51:44.511015 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6899/18540 mark_down [2a00:f10:11b:cef0:225:90ff:fe33:499c]:6814/12657 -- 0x320c000
2012-03-29 11:51:44.511091 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/18540 mark_down 0x2f51140 -- pipe dne
2012-03-29 11:51:44.511138 7f652df2d700 osd.0 33566 note_down_osd osd.31
2012-03-29 11:51:44.511198 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6899/18540 mark_down [2a00:f10:11b:cef0:225:90ff:fe33:499c]:6810/13252 -- 0x30e6c80
2012-03-29 11:51:44.511270 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/18540 mark_down 0x2ce3000 -- pipe dne
2012-03-29 11:51:44.511313 7f652df2d700 osd.0 33566 note_down_osd osd.32
2012-03-29 11:51:44.511373 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6899/18540 mark_down [2a00:f10:11b:cef0:225:90ff:fe33:498e]:6843/13838 -- 0x3d2d000
2012-03-29 11:51:44.511446 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/18540 mark_down 0x2ce3a00 -- pipe dne
2012-03-29 11:51:44.511485 7f652df2d700 osd.0 33566 note_down_osd osd.33
2012-03-29 11:51:44.511543 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6899/18540 mark_down [2a00:f10:11b:cef0:225:90ff:fe33:498e]:6866/14555 -- 0x3108780
2012-03-29 11:51:44.511652 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/18540 mark_down 0x2daec80 -- 0x320cc80
2012-03-29 11:51:44.511739 7f652df2d700 osd.0 33566 note_down_osd osd.34
2012-03-29 11:51:44.511801 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6899/18540 mark_down [2a00:f10:11b:cef0:225:90ff:fe33:498e]:6800/15019 -- 0x35a9a00
2012-03-29 11:51:44.511899 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/18540 mark_down 0x2dae8c0 -- 0x2fd3780
2012-03-29 11:51:44.511988 7f652df2d700 osd.0 33566 note_down_osd osd.35
2012-03-29 11:51:44.512050 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6899/18540 mark_down [2a00:f10:11b:cef0:225:90ff:fe33:498e]:6841/15445 -- 0x2f00000
2012-03-29 11:51:44.512119 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/18540 mark_down 0x2f518c0 -- pipe dne
2012-03-29 11:51:44.512159 7f652df2d700 osd.0 33566 note_down_osd osd.38
2012-03-29 11:51:44.512218 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6899/18540 mark_down [2a00:f10:11b:cef0:225:90ff:fe33:49a4]:6827/18031 -- 0x17fa780
2012-03-29 11:51:44.512290 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/18540 mark_down 0x34fb280 -- pipe dne
2012-03-29 11:51:44.523431 7f652df2d700 osd.0 33567 pg[1.860( empty n=0 ec=1 les/c 33542/33553 33562/33562/33562) [0,38] r=0 lpr=33562 mlcod 0'0 down+peering] state<Started/Primary/Peering>: Peering, affected_by_map, going to Reset
2012-03-29 11:51:44.523655 7f652df2d700 osd.0 33567 pg[0.861( empty n=0 ec=1 les/c 33542/33553 33562/33562/33562) [0,38] r=0 lpr=33562 mlcod 0'0 down+peering] state<Started/Primary/Peering>: Peering, affected_by_map, going to Reset
2012-03-29 11:51:44.523810 7f652df2d700 osd.0 33567 pg[2.85f( v 582'42 (0'0,582'42] n=15 ec=1 les/c 33542/33553 33562/33562/33562) [0,38] r=0 lpr=33562 lcod 0'0 mlcod 0'0 down+peering] state<Started/Primary/Peering>: Peering, affected_by_map, going to Reset
2012-03-29 11:51:44.552887 7f652df2d700 log [WRN] : map e33567 wrongly marked me down or wrong addr
2012-03-29 11:51:44.553074 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6899/18540 mark_down_all
2012-03-29 11:51:44.558154 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:6900/18540 mark_down_all
2012-03-29 11:51:44.562394 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/18540 mark_down_all
2012-03-29 11:51:44.562936 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/18540 mark_down 0x2bc5140 -- 0x3c01a00
2012-03-29 11:51:44.563029 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/18540 mark_down 0x339f8c0 -- 0x3249780
2012-03-29 11:51:44.563095 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/18540 mark_down 0x2c38640 -- 0x2f29500
2012-03-29 11:51:44.563148 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/18540 mark_down 0x32c9a00 -- 0x3d07000
2012-03-29 11:51:44.563199 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/18540 mark_down 0x2671b40 -- 0x3769500
2012-03-29 11:51:44.564070 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/18540 mark_down 0x339f640 -- 0x2e91280
2012-03-29 11:51:44.564199 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/18540 mark_down 0x2f1c000 -- 0x3a7f280
2012-03-29 11:51:44.564256 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/18540 mark_down 0x2b19c80 -- 0x2c01a00
2012-03-29 11:51:44.564305 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/18540 mark_down 0x2b19140 -- 0x3757280
2012-03-29 11:51:44.564350 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/18540 mark_down 0x2f1c780 -- 0x2ce8000
2012-03-29 11:51:44.564399 7f652df2d700 -- [2a00:f10:11b:cef0:225:90ff:fe33:49fe]:0/18540 mark_down 0x2b19dc0 -- 0x2f01000

Still, at random they start marking each other as down.

One moment I have 18/40 OSDs up, the other 38/40 and then 40/40 again.

I played a bit with the heartbeat interval and grace, but that didn't make any difference.

#7 Updated by Sage Weil almost 12 years ago

Der.. do you have a log you can attach/post?

#8 Updated by Wido den Hollander almost 12 years ago

I collected logs from 4 OSDs, they can be downloaded at: http://logger.ceph.widodh.nl/ceph/issues/2212/

At 10:13 this morning I did a rolling upgrade of the cluster, which then resulted in the flapping.

The logs should cover somewhere from 10:13 till 10:59. I think they should hold enough information about what was happening.

#9 Updated by Sage Weil almost 12 years ago

Well, I fixed one problem, but I can't see how it could have resulted in the log you posted.

Pushed a few more patches with that fix and some more debug output. Can you give it another go? If it fails again, please post the logs again too. Thanks!

#10 Updated by Wido den Hollander almost 12 years ago

I think I can be optimistic :)

2012-03-30 09:32:21.380074    pg v662646: 7920 pgs: 7920 active+clean; 242 GB data, 735 GB used, 70786 GB / 74520 GB avail
2012-03-30 09:32:22.481135    pg v662647: 7920 pgs: 7920 active+clean; 242 GB data, 735 GB used, 70786 GB / 74520 GB avail
2012-03-30 09:32:24.996811    pg v662648: 7920 pgs: 7920 active+clean; 242 GB data, 735 GB used, 70786 GB / 74520 GB avail
2012-03-30 09:32:26.429189    pg v662649: 7920 pgs: 7920 active+clean; 242 GB data, 735 GB used, 70786 GB / 74520 GB avail
2012-03-30 09:32:27.471180    pg v662650: 7920 pgs: 7920 active+clean; 242 GB data, 735 GB used, 70786 GB / 74520 GB avail
2012-03-30 09:32:31.409230    pg v662651: 7920 pgs: 7920 active+clean; 242 GB data, 735 GB used, 70786 GB / 74520 GB avail
2012-03-30 09:32:32.485143    pg v662652: 7920 pgs: 7920 active+clean; 242 GB data, 735 GB used, 70786 GB / 74520 GB avail
2012-03-30 09:32:36.448658    pg v662653: 7920 pgs: 7920 active+clean; 242 GB data, 735 GB used, 70786 GB / 74520 GB avail
2012-03-30 09:32:37.508033    pg v662654: 7920 pgs: 7920 active+clean; 242 GB data, 735 GB used, 70786 GB / 74520 GB avail
2012-03-30 09:32:41.413145    pg v662655: 7920 pgs: 7920 active+clean; 242 GB data, 735 GB used, 70786 GB / 74520 GB avail
2012-03-30 09:32:42.489055    pg v662656: 7920 pgs: 7920 active+clean; 242 GB data, 735 GB used, 70786 GB / 74520 GB avail
2012-03-30 09:32:46.443998    pg v662657: 7920 pgs: 7920 active+clean; 242 GB data, 735 GB used, 70786 GB / 74520 GB avail
2012-03-30 09:32:47.528569    pg v662658: 7920 pgs: 7920 active+clean; 242 GB data, 735 GB used, 70786 GB / 74520 GB avail
2012-03-30 09:32:51.450257    pg v662659: 7920 pgs: 7920 active+clean; 242 GB data, 735 GB used, 70786 GB / 74520 GB avail
2012-03-30 09:32:52.526373    pg v662660: 7920 pgs: 7920 active+clean; 242 GB data, 735 GB used, 70786 GB / 74520 GB avail
2012-03-30 09:32:56.431498    pg v662661: 7920 pgs: 7920 active+clean; 242 GB data, 735 GB used, 70786 GB / 74520 GB avail
2012-03-30 09:32:57.532241    pg v662662: 7920 pgs: 7920 active+clean; 242 GB data, 735 GB used, 70786 GB / 74520 GB avail
2012-03-30 09:33:01.445757    pg v662663: 7920 pgs: 7920 active+clean; 242 GB data, 735 GB used, 70786 GB / 74520 GB avail
2012-03-30 09:33:06.518762    pg v662664: 7920 pgs: 7920 active+clean; 242 GB data, 735 GB used, 70786 GB / 74520 GB avail
2012-03-30 09:33:07.627921    pg v662665: 7920 pgs: 7920 active+clean; 242 GB data, 735 GB used, 70786 GB / 74520 GB avail
2012-03-30 09:33:11.491287    pg v662666: 7920 pgs: 7920 active+clean; 242 GB data, 735 GB used, 70786 GB / 74520 GB avail
2012-03-30 09:33:12.550495    pg v662667: 7920 pgs: 7920 active+clean; 242 GB data, 735 GB used, 70786 GB / 74520 GB avail
2012-03-30 09:33:16.480825    pg v662668: 7920 pgs: 7920 active+clean; 242 GB data, 735 GB used, 70786 GB / 74520 GB avail
2012-03-30 09:33:17.573618    pg v662669: 7920 pgs: 7920 active+clean; 242 GB data, 735 GB used, 70786 GB / 74520 GB avail
2012-03-30 09:33:21.470318    pg v662670: 7920 pgs: 7920 active+clean; 242 GB data, 735 GB used, 70786 GB / 74520 GB avail
2012-03-30 09:33:22.554549    pg v662671: 7920 pgs: 7920 active+clean; 242 GB data, 735 GB used, 70786 GB / 74520 GB avail
2012-03-30 09:33:26.476305    pg v662672: 7920 pgs: 7920 active+clean; 242 GB data, 735 GB used, 70786 GB / 74520 GB avail
2012-03-30 09:33:27.552456    pg v662673: 7920 pgs: 7920 active+clean; 242 GB data, 735 GB used, 70786 GB / 74520 GB avail
2012-03-30 09:33:31.482636    pg v662674: 7920 pgs: 7920 active+clean; 242 GB data, 735 GB used, 70786 GB / 74520 GB avail
2012-03-30 09:33:32.583697    pg v662675: 7920 pgs: 7920 active+clean; 242 GB data, 735 GB used, 70786 GB / 74520 GB avail

That seems much better, doesn't it?

This new code stabilized very quickly, within just 2 minutes of the last OSD reboot it became active+clean for all PG's.

The load on all the systems is also very low:

root@monitor:~# dsh -g osd uptime
 09:34:29 up 2 days, 17:30,  1 user,  load average: 0.13, 0.12, 0.45
 09:34:30 up 2 days, 17:12,  1 user,  load average: 0.01, 0.06, 0.34
 09:34:31 up 2 days, 14:52,  1 user,  load average: 0.04, 0.14, 0.42
 09:34:32 up 2 days, 14:45,  1 user,  load average: 0.11, 0.06, 0.24
 09:34:33 up 2 days, 14:42,  1 user,  load average: 0.16, 0.12, 0.31
 09:34:34 up 2 days, 14:39,  1 user,  load average: 0.04, 0.10, 0.38
 09:34:35 up 2 days, 14:34,  1 user,  load average: 0.17, 0.13, 0.53
 09:34:37 up 2 days, 14:30,  1 user,  load average: 0.08, 0.05, 0.25
 09:34:38 up 2 days, 14:26,  1 user,  load average: 0.02, 0.07, 0.29
 09:34:39 up 2 days, 14:22,  1 user,  load average: 0.01, 0.07, 0.29
root@monitor:~#

The heartbeat and grace periods are both set back to their defaults.

#11 Updated by Sage Weil almost 12 years ago

  • Status changed from 12 to Resolved

Also available in: Atom PDF