1 // -*- mode:C++; tab-width:8; c-basic-offset:2; indent-tabs-mode:t -*-
2 // vim: ts=8 sw=2 smarttab
4 * Ceph - scalable distributed file system
6 * Copyright (C) 2004-2006 Sage Weil <sage@newdream.net>
8 * This is free software; you can redistribute it and/or
9 * modify it under the terms of the GNU Lesser General Public
10 * License version 2.1, as published by the Free Software
11 * Foundation. See file COPYING.
19 #include "MDSContext.h"
21 #include "osdc/Journaler.h"
22 #include "mds/JournalPointer.h"
24 #include "common/entity_name.h"
25 #include "common/perf_counters.h"
26 #include "common/Cond.h"
28 #include "events/ESubtreeMap.h"
30 #include "common/config.h"
31 #include "common/errno.h"
32 #include "include/assert.h"
34 #define dout_context g_ceph_context
35 #define dout_subsys ceph_subsys_mds
37 #define dout_prefix *_dout << "mds." << mds->get_nodeid() << ".log "
42 if (journaler
) { delete journaler
; journaler
= 0; }
44 g_ceph_context
->get_perfcounters_collection()->remove(logger
);
51 void MDLog::create_logger()
53 PerfCountersBuilder
plb(g_ceph_context
, "mds_log", l_mdl_first
, l_mdl_last
);
55 plb
.add_u64_counter(l_mdl_evadd
, "evadd",
56 "Events submitted", "subm", PerfCountersBuilder::PRIO_INTERESTING
);
57 plb
.add_u64_counter(l_mdl_evex
, "evex", "Total expired events");
58 plb
.add_u64_counter(l_mdl_evtrm
, "evtrm", "Trimmed events");
59 plb
.add_u64(l_mdl_ev
, "ev",
60 "Events", "evts", PerfCountersBuilder::PRIO_INTERESTING
);
61 plb
.add_u64(l_mdl_evexg
, "evexg", "Expiring events");
62 plb
.add_u64(l_mdl_evexd
, "evexd", "Current expired events");
64 plb
.add_u64_counter(l_mdl_segadd
, "segadd", "Segments added");
65 plb
.add_u64_counter(l_mdl_segex
, "segex", "Total expired segments");
66 plb
.add_u64_counter(l_mdl_segtrm
, "segtrm", "Trimmed segments");
67 plb
.add_u64(l_mdl_seg
, "seg",
68 "Segments", "segs", PerfCountersBuilder::PRIO_INTERESTING
);
69 plb
.add_u64(l_mdl_segexg
, "segexg", "Expiring segments");
70 plb
.add_u64(l_mdl_segexd
, "segexd", "Current expired segments");
72 plb
.add_u64(l_mdl_expos
, "expos", "Journaler xpire position");
73 plb
.add_u64(l_mdl_wrpos
, "wrpos", "Journaler write position");
74 plb
.add_u64(l_mdl_rdpos
, "rdpos", "Journaler read position");
75 plb
.add_time_avg(l_mdl_jlat
, "jlat", "Journaler flush latency");
77 plb
.add_u64_counter(l_mdl_replayed
, "replayed", "Events replayed");
80 logger
= plb
.create_perf_counters();
81 g_ceph_context
->get_perfcounters_collection()->add(logger
);
84 void MDLog::set_write_iohint(unsigned iohint_flags
)
86 journaler
->set_write_iohint(iohint_flags
);
89 class C_MDL_WriteError
: public MDSIOContextBase
{
92 MDSRank
*get_mds() override
{return mdlog
->mds
;}
94 void finish(int r
) override
{
95 MDSRank
*mds
= get_mds();
96 // assume journal is reliable, so don't choose action based on
97 // g_conf->mds_action_on_write_error.
98 if (r
== -EBLACKLISTED
) {
99 derr
<< "we have been blacklisted (fenced), respawning..." << dendl
;
102 derr
<< "unhandled error " << cpp_strerror(r
) << ", shutting down..." << dendl
;
103 // Although it's possible that this could be something transient,
104 // it's severe and scary, so disable this rank until an administrator
106 mds
->clog
->error() << "Unhandled journal write error on MDS rank " <<
107 mds
->get_nodeid() << ": " << cpp_strerror(r
) << ", shutting down.";
109 ceph_abort(); // damaged should never return
114 explicit C_MDL_WriteError(MDLog
*m
) : mdlog(m
) {}
118 void MDLog::write_head(MDSInternalContextBase
*c
)
122 fin
= new C_IO_Wrapper(mds
, c
);
124 journaler
->write_head(fin
);
127 uint64_t MDLog::get_read_pos() const
129 return journaler
->get_read_pos();
132 uint64_t MDLog::get_write_pos() const
134 return journaler
->get_write_pos();
137 uint64_t MDLog::get_safe_pos() const
139 return journaler
->get_write_safe_pos();
144 void MDLog::create(MDSInternalContextBase
*c
)
146 dout(5) << "create empty log" << dendl
;
148 C_GatherBuilder
gather(g_ceph_context
);
149 // This requires an OnFinisher wrapper because Journaler will call back the completion for write_head inside its own lock
150 // XXX but should maybe that be handled inside Journaler?
151 gather
.set_finisher(new C_IO_Wrapper(mds
, c
));
153 // The inode of the default Journaler we will create
154 ino
= MDS_INO_LOG_OFFSET
+ mds
->get_nodeid();
156 // Instantiate Journaler and start async write to RADOS
157 assert(journaler
== NULL
);
158 journaler
= new Journaler("mdlog", ino
, mds
->mdsmap
->get_metadata_pool(),
159 CEPH_FS_ONDISK_MAGIC
, mds
->objecter
, logger
,
160 l_mdl_jlat
, mds
->finisher
);
161 assert(journaler
->is_readonly());
162 journaler
->set_write_error_handler(new C_MDL_WriteError(this));
163 journaler
->set_writeable();
164 journaler
->create(&mds
->mdcache
->default_log_layout
, g_conf
->mds_journal_format
);
165 journaler
->write_head(gather
.new_sub());
167 // Async write JournalPointer to RADOS
168 JournalPointer
jp(mds
->get_nodeid(), mds
->mdsmap
->get_metadata_pool());
171 jp
.save(mds
->objecter
, gather
.new_sub());
175 logger
->set(l_mdl_expos
, journaler
->get_expire_pos());
176 logger
->set(l_mdl_wrpos
, journaler
->get_write_pos());
178 submit_thread
.create("md_submit");
181 void MDLog::open(MDSInternalContextBase
*c
)
183 dout(5) << "open discovering log bounds" << dendl
;
185 assert(!recovery_thread
.is_started());
186 recovery_thread
.set_completion(c
);
187 recovery_thread
.create("md_recov_open");
189 submit_thread
.create("md_submit");
190 // either append() or replay() will follow.
194 * Final part of reopen() procedure, after recovery_thread
195 * has done its thing we call append()
197 class C_ReopenComplete
: public MDSInternalContext
{
199 MDSInternalContextBase
*on_complete
;
201 C_ReopenComplete(MDLog
*mdlog_
, MDSInternalContextBase
*on_complete_
) : MDSInternalContext(mdlog_
->mds
), mdlog(mdlog_
), on_complete(on_complete_
) {}
202 void finish(int r
) override
{
204 on_complete
->complete(r
);
209 * Given that open() has been called in the past, go through the journal
210 * recovery procedure again, potentially reformatting the journal if it
211 * was in an old format.
213 void MDLog::reopen(MDSInternalContextBase
*c
)
215 dout(5) << "reopen" << dendl
;
217 // Because we will call append() at the completion of this, check that we have already
218 // read the whole journal.
219 assert(journaler
!= NULL
);
220 assert(journaler
->get_read_pos() == journaler
->get_write_pos());
225 // recovery_thread was started at some point in the past. Although
226 // it has called it's completion if we made it back here, it might
227 // still not have been cleaned up: join it.
228 recovery_thread
.join();
230 recovery_thread
.set_completion(new C_ReopenComplete(this, c
));
231 recovery_thread
.create("md_recov_reopen");
236 dout(5) << "append positioning at end and marking writeable" << dendl
;
237 journaler
->set_read_pos(journaler
->get_write_pos());
238 journaler
->set_expire_pos(journaler
->get_write_pos());
240 journaler
->set_writeable();
242 logger
->set(l_mdl_expos
, journaler
->get_write_pos());
247 // -------------------------------------------------
249 void MDLog::_start_entry(LogEvent
*e
)
251 assert(submit_mutex
.is_locked_by_me());
253 assert(cur_event
== NULL
);
258 EMetaBlob
*metablob
= e
->get_metablob();
260 metablob
->event_seq
= event_seq
;
261 metablob
->last_subtree_map
= get_last_segment_seq();
265 void MDLog::cancel_entry(LogEvent
*le
)
267 assert(le
== cur_event
);
272 void MDLog::_submit_entry(LogEvent
*le
, MDSLogContextBase
*c
)
274 assert(submit_mutex
.is_locked_by_me());
275 assert(!mds
->is_any_replay());
278 assert(le
== cur_event
);
281 // let the event register itself in the segment
282 assert(!segments
.empty());
283 LogSegment
*ls
= segments
.rbegin()->second
;
287 le
->update_segment();
288 le
->set_stamp(ceph_clock_now());
290 mdsmap_up_features
= mds
->mdsmap
->get_up_features();
291 pending_events
[ls
->seq
].push_back(PendingEvent(le
, c
));
295 logger
->inc(l_mdl_evadd
);
296 logger
->set(l_mdl_ev
, num_events
);
301 uint64_t period
= journaler
->get_layout_period();
302 // start a new segment?
303 if (le
->get_type() == EVENT_SUBTREEMAP
||
304 (le
->get_type() == EVENT_IMPORTFINISH
&& mds
->is_resolve())) {
305 // avoid infinite loop when ESubtreeMap is very large.
306 // do not insert ESubtreeMap among EImportFinish events that finish
307 // disambiguate imports. Because the ESubtreeMap reflects the subtree
308 // state when all EImportFinish events are replayed.
309 } else if (ls
->end
/period
!= ls
->offset
/period
||
310 ls
->num_events
>= g_conf
->mds_log_events_per_segment
) {
311 dout(10) << "submit_entry also starting new segment: last = "
312 << ls
->seq
<< "/" << ls
->offset
<< ", event seq = " << event_seq
<< dendl
;
313 _start_new_segment();
314 } else if (g_conf
->mds_debug_subtrees
&&
315 le
->get_type() != EVENT_SUBTREEMAP_TEST
) {
316 // debug: journal this every time to catch subtree replay bugs.
317 // use a different event id so it doesn't get interpreted as a
318 // LogSegment boundary on replay.
319 LogEvent
*sle
= mds
->mdcache
->create_subtree_map();
320 sle
->set_type(EVENT_SUBTREEMAP_TEST
);
321 _submit_entry(sle
, NULL
);
326 * Invoked on the flush after each entry submitted
328 class C_MDL_Flushed
: public MDSLogContextBase
{
331 MDSRank
*get_mds() override
{return mdlog
->mds
;}
332 MDSInternalContextBase
*wrapped
;
334 void finish(int r
) override
{
336 wrapped
->complete(r
);
340 C_MDL_Flushed(MDLog
*m
, MDSInternalContextBase
*w
)
341 : mdlog(m
), wrapped(w
) {}
342 C_MDL_Flushed(MDLog
*m
, uint64_t wp
) : mdlog(m
), wrapped(NULL
) {
347 void MDLog::_submit_thread()
349 dout(10) << "_submit_thread start" << dendl
;
353 while (!mds
->is_daemon_stopping()) {
354 if (g_conf
->mds_log_pause
) {
355 submit_cond
.Wait(submit_mutex
);
359 map
<uint64_t,list
<PendingEvent
> >::iterator it
= pending_events
.begin();
360 if (it
== pending_events
.end()) {
361 submit_cond
.Wait(submit_mutex
);
365 if (it
->second
.empty()) {
366 pending_events
.erase(it
);
370 int64_t features
= mdsmap_up_features
;
371 PendingEvent data
= it
->second
.front();
372 it
->second
.pop_front();
374 submit_mutex
.Unlock();
377 LogEvent
*le
= data
.le
;
378 LogSegment
*ls
= le
->_segment
;
379 // encode it, with event type
381 le
->encode_with_header(bl
, features
);
383 uint64_t write_pos
= journaler
->get_write_pos();
385 le
->set_start_off(write_pos
);
386 if (le
->get_type() == EVENT_SUBTREEMAP
)
387 ls
->offset
= write_pos
;
389 dout(5) << "_submit_thread " << write_pos
<< "~" << bl
.length()
390 << " : " << *le
<< dendl
;
393 const uint64_t new_write_pos
= journaler
->append_entry(bl
); // bl is destroyed.
394 ls
->end
= new_write_pos
;
396 MDSLogContextBase
*fin
;
398 fin
= dynamic_cast<MDSLogContextBase
*>(data
.fin
);
400 fin
->set_write_pos(new_write_pos
);
402 fin
= new C_MDL_Flushed(this, new_write_pos
);
405 journaler
->wait_for_flush(fin
);
411 logger
->set(l_mdl_wrpos
, ls
->end
);
416 MDSInternalContextBase
* fin
=
417 dynamic_cast<MDSInternalContextBase
*>(data
.fin
);
419 C_MDL_Flushed
*fin2
= new C_MDL_Flushed(this, fin
);
420 fin2
->set_write_pos(journaler
->get_write_pos());
421 journaler
->wait_for_flush(fin2
);
434 submit_mutex
.Unlock();
437 void MDLog::wait_for_safe(MDSInternalContextBase
*c
)
441 bool no_pending
= true;
442 if (!pending_events
.empty()) {
443 pending_events
.rbegin()->second
.push_back(PendingEvent(NULL
, c
));
445 submit_cond
.Signal();
448 submit_mutex
.Unlock();
451 journaler
->wait_for_flush(new C_IO_Wrapper(mds
, c
));
458 bool do_flush
= unflushed
> 0;
460 if (!pending_events
.empty()) {
461 pending_events
.rbegin()->second
.push_back(PendingEvent(NULL
, NULL
, true));
463 submit_cond
.Signal();
466 submit_mutex
.Unlock();
472 void MDLog::kick_submitter()
474 Mutex::Locker
l(submit_mutex
);
475 submit_cond
.Signal();
480 dout(5) << "cap" << dendl
;
484 void MDLog::shutdown()
486 assert(mds
->mds_lock
.is_locked_by_me());
488 dout(5) << "shutdown" << dendl
;
489 if (submit_thread
.is_started()) {
490 assert(mds
->is_daemon_stopping());
492 if (submit_thread
.am_self()) {
493 // Called suicide from the thread: trust it to do no work after
494 // returning from suicide, and subsequently respect mds->is_daemon_stopping()
495 // and fall out of its loop.
497 mds
->mds_lock
.Unlock();
498 // Because MDS::stopping is true, it's safe to drop mds_lock: nobody else
499 // picking it up will do anything with it.
502 submit_cond
.Signal();
503 submit_mutex
.Unlock();
505 mds
->mds_lock
.Lock();
507 submit_thread
.join();
511 // Replay thread can be stuck inside e.g. Journaler::wait_for_readable,
512 // so we need to shutdown the journaler first.
514 journaler
->shutdown();
517 if (replay_thread
.is_started() && !replay_thread
.am_self()) {
518 mds
->mds_lock
.Unlock();
519 replay_thread
.join();
520 mds
->mds_lock
.Lock();
523 if (recovery_thread
.is_started() && !recovery_thread
.am_self()) {
524 mds
->mds_lock
.Unlock();
525 recovery_thread
.join();
526 mds
->mds_lock
.Lock();
531 // -----------------------------
534 void MDLog::_start_new_segment()
536 _prepare_new_segment();
537 _journal_segment_subtree_map(NULL
);
540 void MDLog::_prepare_new_segment()
542 assert(submit_mutex
.is_locked_by_me());
544 uint64_t seq
= event_seq
+ 1;
545 dout(7) << __func__
<< " seq " << seq
<< dendl
;
547 segments
[seq
] = new LogSegment(seq
);
549 logger
->inc(l_mdl_segadd
);
550 logger
->set(l_mdl_seg
, segments
.size());
552 // Adjust to next stray dir
553 dout(10) << "Advancing to next stray directory on mds " << mds
->get_nodeid()
555 mds
->mdcache
->advance_stray();
558 void MDLog::_journal_segment_subtree_map(MDSInternalContextBase
*onsync
)
560 assert(submit_mutex
.is_locked_by_me());
562 dout(7) << __func__
<< dendl
;
563 ESubtreeMap
*sle
= mds
->mdcache
->create_subtree_map();
564 sle
->event_seq
= get_last_segment_seq();
566 _submit_entry(sle
, new C_MDL_Flushed(this, onsync
));
569 void MDLog::trim(int m
)
571 unsigned max_segments
= g_conf
->mds_log_max_segments
;
572 int max_events
= g_conf
->mds_log_max_events
;
576 if (mds
->mdcache
->is_readonly()) {
577 dout(10) << "trim, ignoring read-only FS" << dendl
;
581 // Clamp max_events to not be smaller than events per segment
582 if (max_events
> 0 && max_events
<= g_conf
->mds_log_events_per_segment
) {
583 max_events
= g_conf
->mds_log_events_per_segment
+ 1;
590 << segments
.size() << " / " << max_segments
<< " segments, "
591 << num_events
<< " / " << max_events
<< " events"
592 << ", " << expiring_segments
.size() << " (" << expiring_events
<< ") expiring"
593 << ", " << expired_segments
.size() << " (" << expired_events
<< ") expired"
596 if (segments
.empty()) {
597 submit_mutex
.Unlock();
601 // hack: only trim for a few seconds at a time
602 utime_t stop
= ceph_clock_now();
605 int op_prio
= CEPH_MSG_PRIO_LOW
+
606 (CEPH_MSG_PRIO_HIGH
- CEPH_MSG_PRIO_LOW
) *
607 expiring_segments
.size() / max_segments
;
608 if (op_prio
> CEPH_MSG_PRIO_HIGH
)
609 op_prio
= CEPH_MSG_PRIO_HIGH
;
611 unsigned new_expiring_segments
= 0;
613 map
<uint64_t,LogSegment
*>::iterator p
= segments
.begin();
614 while (p
!= segments
.end()) {
615 if (stop
< ceph_clock_now())
618 unsigned num_remaining_segments
= (segments
.size() - expired_segments
.size() - expiring_segments
.size());
619 if ((num_remaining_segments
<= max_segments
) &&
620 (max_events
< 0 || num_events
- expiring_events
- expired_events
<= max_events
))
623 // Do not trim too many segments at once for peak workload. If mds keeps creating N segments each tick,
624 // the upper bound of 'num_remaining_segments - max_segments' is '2 * N'
625 if (new_expiring_segments
* 2 > num_remaining_segments
)
628 // look at first segment
629 LogSegment
*ls
= p
->second
;
633 if (pending_events
.count(ls
->seq
) ||
634 ls
->end
> safe_pos
) {
635 dout(5) << "trim segment " << ls
->seq
<< "/" << ls
->offset
<< ", not fully flushed yet, safe "
636 << journaler
->get_write_safe_pos() << " < end " << ls
->end
<< dendl
;
639 if (expiring_segments
.count(ls
)) {
640 dout(5) << "trim already expiring segment " << ls
->seq
<< "/" << ls
->offset
641 << ", " << ls
->num_events
<< " events" << dendl
;
642 } else if (expired_segments
.count(ls
)) {
643 dout(5) << "trim already expired segment " << ls
->seq
<< "/" << ls
->offset
644 << ", " << ls
->num_events
<< " events" << dendl
;
646 assert(expiring_segments
.count(ls
) == 0);
647 new_expiring_segments
++;
648 expiring_segments
.insert(ls
);
649 expiring_events
+= ls
->num_events
;
650 submit_mutex
.Unlock();
652 uint64_t last_seq
= ls
->seq
;
653 try_expire(ls
, op_prio
);
656 p
= segments
.lower_bound(last_seq
+ 1);
660 // discard expired segments and unlock submit_mutex
661 _trim_expired_segments();
664 class C_MaybeExpiredSegment
: public MDSInternalContext
{
669 C_MaybeExpiredSegment(MDLog
*mdl
, LogSegment
*s
, int p
) :
670 MDSInternalContext(mdl
->mds
), mdlog(mdl
), ls(s
), op_prio(p
) {}
671 void finish(int res
) override
{
673 mdlog
->mds
->handle_write_error(res
);
674 mdlog
->_maybe_expired(ls
, op_prio
);
679 * Like MDLog::trim, but instead of trimming to max_segments, trim all but the latest
682 int MDLog::trim_all()
686 dout(10) << __func__
<< ": "
688 << "/" << expiring_segments
.size()
689 << "/" << expired_segments
.size() << dendl
;
691 uint64_t last_seq
= 0;
692 if (!segments
.empty())
693 last_seq
= get_last_segment_seq();
695 map
<uint64_t,LogSegment
*>::iterator p
= segments
.begin();
696 while (p
!= segments
.end() &&
697 p
->first
< last_seq
&& p
->second
->end
<= safe_pos
) {
698 LogSegment
*ls
= p
->second
;
701 // Caller should have flushed journaler before calling this
702 if (pending_events
.count(ls
->seq
)) {
703 dout(5) << __func__
<< ": segment " << ls
->seq
<< " has pending events" << dendl
;
704 submit_mutex
.Unlock();
708 if (expiring_segments
.count(ls
)) {
709 dout(5) << "trim already expiring segment " << ls
->seq
<< "/" << ls
->offset
710 << ", " << ls
->num_events
<< " events" << dendl
;
711 } else if (expired_segments
.count(ls
)) {
712 dout(5) << "trim already expired segment " << ls
->seq
<< "/" << ls
->offset
713 << ", " << ls
->num_events
<< " events" << dendl
;
715 assert(expiring_segments
.count(ls
) == 0);
716 expiring_segments
.insert(ls
);
717 expiring_events
+= ls
->num_events
;
718 submit_mutex
.Unlock();
720 uint64_t next_seq
= ls
->seq
+ 1;
721 try_expire(ls
, CEPH_MSG_PRIO_DEFAULT
);
724 p
= segments
.lower_bound(next_seq
);
728 _trim_expired_segments();
734 void MDLog::try_expire(LogSegment
*ls
, int op_prio
)
736 MDSGatherBuilder
gather_bld(g_ceph_context
);
737 ls
->try_to_expire(mds
, gather_bld
, op_prio
);
739 if (gather_bld
.has_subs()) {
740 dout(5) << "try_expire expiring segment " << ls
->seq
<< "/" << ls
->offset
<< dendl
;
741 gather_bld
.set_finisher(new C_MaybeExpiredSegment(this, ls
, op_prio
));
742 gather_bld
.activate();
744 dout(10) << "try_expire expired segment " << ls
->seq
<< "/" << ls
->offset
<< dendl
;
746 assert(expiring_segments
.count(ls
));
747 expiring_segments
.erase(ls
);
748 expiring_events
-= ls
->num_events
;
750 submit_mutex
.Unlock();
753 logger
->set(l_mdl_segexg
, expiring_segments
.size());
754 logger
->set(l_mdl_evexg
, expiring_events
);
757 void MDLog::_maybe_expired(LogSegment
*ls
, int op_prio
)
759 if (mds
->mdcache
->is_readonly()) {
760 dout(10) << "_maybe_expired, ignoring read-only FS" << dendl
;
764 dout(10) << "_maybe_expired segment " << ls
->seq
<< "/" << ls
->offset
765 << ", " << ls
->num_events
<< " events" << dendl
;
766 try_expire(ls
, op_prio
);
769 void MDLog::_trim_expired_segments()
771 assert(submit_mutex
.is_locked_by_me());
773 // trim expired segments?
774 bool trimmed
= false;
775 while (!segments
.empty()) {
776 LogSegment
*ls
= segments
.begin()->second
;
777 if (!expired_segments
.count(ls
)) {
778 dout(10) << "_trim_expired_segments waiting for " << ls
->seq
<< "/" << ls
->offset
779 << " to expire" << dendl
;
783 dout(10) << "_trim_expired_segments trimming expired "
784 << ls
->seq
<< "/0x" << std::hex
<< ls
->offset
<< std::dec
<< dendl
;
785 expired_events
-= ls
->num_events
;
786 expired_segments
.erase(ls
);
787 num_events
-= ls
->num_events
;
789 // this was the oldest segment, adjust expire pos
790 if (journaler
->get_expire_pos() < ls
->end
) {
791 journaler
->set_expire_pos(ls
->end
);
792 logger
->set(l_mdl_expos
, ls
->end
);
794 logger
->set(l_mdl_expos
, ls
->offset
);
797 logger
->inc(l_mdl_segtrm
);
798 logger
->inc(l_mdl_evtrm
, ls
->num_events
);
800 segments
.erase(ls
->seq
);
805 submit_mutex
.Unlock();
808 journaler
->write_head(0);
811 void MDLog::trim_expired_segments()
814 _trim_expired_segments();
817 void MDLog::_expired(LogSegment
*ls
)
819 assert(submit_mutex
.is_locked_by_me());
821 dout(5) << "_expired segment " << ls
->seq
<< "/" << ls
->offset
822 << ", " << ls
->num_events
<< " events" << dendl
;
824 if (!capped
&& ls
== peek_current_segment()) {
825 dout(5) << "_expired not expiring " << ls
->seq
<< "/" << ls
->offset
826 << ", last one and !capped" << dendl
;
829 expired_segments
.insert(ls
);
830 expired_events
+= ls
->num_events
;
832 // Trigger all waiters
833 for (std::list
<MDSInternalContextBase
*>::iterator i
= ls
->expiry_waiters
.begin();
834 i
!= ls
->expiry_waiters
.end(); ++i
) {
837 ls
->expiry_waiters
.clear();
839 logger
->inc(l_mdl_evex
, ls
->num_events
);
840 logger
->inc(l_mdl_segex
);
843 logger
->set(l_mdl_ev
, num_events
);
844 logger
->set(l_mdl_evexd
, expired_events
);
845 logger
->set(l_mdl_seg
, segments
.size());
846 logger
->set(l_mdl_segexd
, expired_segments
.size());
851 void MDLog::replay(MDSInternalContextBase
*c
)
853 assert(journaler
->is_active());
854 assert(journaler
->is_readonly());
857 if (journaler
->get_read_pos() == journaler
->get_write_pos()) {
858 dout(10) << "replay - journal empty, done." << dendl
;
859 mds
->mdcache
->trim();
868 waitfor_replay
.push_back(c
);
871 dout(10) << "replay start, from " << journaler
->get_read_pos()
872 << " to " << journaler
->get_write_pos() << dendl
;
874 assert(num_events
== 0 || already_replayed
);
875 if (already_replayed
) {
876 // Ensure previous instance of ReplayThread is joined before
877 // we create another one
878 replay_thread
.join();
880 already_replayed
= true;
882 replay_thread
.create("md_log_replay");
887 * Resolve the JournalPointer object to a journal file, and
888 * instantiate a Journaler object. This may re-write the journal
889 * if the journal in RADOS appears to be in an old format.
891 * This is a separate thread because of the way it is initialized from inside
892 * the mds lock, which is also the global objecter lock -- rather than split
893 * it up into hard-to-read async operations linked up by contexts,
895 * When this function completes, the `journaler` attribute will be set to
896 * a Journaler instance using the latest available serialization format.
898 void MDLog::_recovery_thread(MDSInternalContextBase
*completion
)
900 assert(journaler
== NULL
);
901 if (g_conf
->mds_journal_format
> JOURNAL_FORMAT_MAX
) {
902 dout(0) << "Configuration value for mds_journal_format is out of bounds, max is "
903 << JOURNAL_FORMAT_MAX
<< dendl
;
905 // Oh dear, something unreadable in the store for this rank: require
906 // operator intervention.
908 ceph_abort(); // damaged should not return
911 // First, read the pointer object.
912 // If the pointer object is not present, then create it with
913 // front = default ino and back = null
914 JournalPointer
jp(mds
->get_nodeid(), mds
->mdsmap
->get_metadata_pool());
915 const int read_result
= jp
.load(mds
->objecter
);
916 if (read_result
== -ENOENT
) {
917 inodeno_t
const default_log_ino
= MDS_INO_LOG_OFFSET
+ mds
->get_nodeid();
918 jp
.front
= default_log_ino
;
919 int write_result
= jp
.save(mds
->objecter
);
920 // Nothing graceful we can do for this
921 assert(write_result
>= 0);
922 } else if (read_result
== -EBLACKLISTED
) {
923 derr
<< "Blacklisted during JournalPointer read! Respawning..." << dendl
;
925 ceph_abort(); // Should be unreachable because respawn calls execv
926 } else if (read_result
!= 0) {
927 mds
->clog
->error() << "failed to read JournalPointer: " << read_result
928 << " (" << cpp_strerror(read_result
) << ")";
929 mds
->damaged_unlocked();
930 ceph_abort(); // Should be unreachable because damaged() calls respawn()
933 // If the back pointer is non-null, that means that a journal
934 // rewrite failed part way through. Erase the back journal
937 if (mds
->is_standby_replay()) {
938 dout(1) << "Journal " << jp
.front
<< " is being rewritten, "
939 << "cannot replay in standby until an active MDS completes rewrite" << dendl
;
940 Mutex::Locker
l(mds
->mds_lock
);
941 if (mds
->is_daemon_stopping()) {
944 completion
->complete(-EAGAIN
);
947 dout(1) << "Erasing journal " << jp
.back
<< dendl
;
948 C_SaferCond erase_waiter
;
949 Journaler
back("mdlog", jp
.back
, mds
->mdsmap
->get_metadata_pool(),
950 CEPH_FS_ONDISK_MAGIC
, mds
->objecter
, logger
, l_mdl_jlat
,
953 // Read all about this journal (header + extents)
954 C_SaferCond recover_wait
;
955 back
.recover(&recover_wait
);
956 int recovery_result
= recover_wait
.wait();
957 if (recovery_result
== -EBLACKLISTED
) {
958 derr
<< "Blacklisted during journal recovery! Respawning..." << dendl
;
960 ceph_abort(); // Should be unreachable because respawn calls execv
961 } else if (recovery_result
!= 0) {
962 // Journaler.recover succeeds if no journal objects are present: an error
963 // means something worse like a corrupt header, which we can't handle here.
964 mds
->clog
->error() << "Error recovering journal " << jp
.front
<< ": "
965 << cpp_strerror(recovery_result
);
966 mds
->damaged_unlocked();
967 assert(recovery_result
== 0); // Unreachable because damaged() calls respawn()
970 // We could read journal, so we can erase it.
971 back
.erase(&erase_waiter
);
972 int erase_result
= erase_waiter
.wait();
974 // If we are successful, or find no data, we can update the JournalPointer to
975 // reflect that the back journal is gone.
976 if (erase_result
!= 0 && erase_result
!= -ENOENT
) {
977 derr
<< "Failed to erase journal " << jp
.back
<< ": " << cpp_strerror(erase_result
) << dendl
;
979 dout(1) << "Successfully erased journal, updating journal pointer" << dendl
;
981 int write_result
= jp
.save(mds
->objecter
);
982 // Nothing graceful we can do for this
983 assert(write_result
>= 0);
987 /* Read the header from the front journal */
988 Journaler
*front_journal
= new Journaler("mdlog", jp
.front
,
989 mds
->mdsmap
->get_metadata_pool(), CEPH_FS_ONDISK_MAGIC
, mds
->objecter
,
990 logger
, l_mdl_jlat
, mds
->finisher
);
992 // Assign to ::journaler so that we can be aborted by ::shutdown while
993 // waiting for journaler recovery
995 Mutex::Locker
l(mds
->mds_lock
);
996 journaler
= front_journal
;
999 C_SaferCond recover_wait
;
1000 front_journal
->recover(&recover_wait
);
1001 dout(4) << "Waiting for journal " << jp
.front
<< " to recover..." << dendl
;
1002 int recovery_result
= recover_wait
.wait();
1003 dout(4) << "Journal " << jp
.front
<< " recovered." << dendl
;
1005 if (recovery_result
== -EBLACKLISTED
) {
1006 derr
<< "Blacklisted during journal recovery! Respawning..." << dendl
;
1008 ceph_abort(); // Should be unreachable because respawn calls execv
1009 } else if (recovery_result
!= 0) {
1010 mds
->clog
->error() << "Error recovering journal " << jp
.front
<< ": "
1011 << cpp_strerror(recovery_result
);
1012 mds
->damaged_unlocked();
1013 assert(recovery_result
== 0); // Unreachable because damaged() calls respawn()
1016 /* Check whether the front journal format is acceptable or needs re-write */
1017 if (front_journal
->get_stream_format() > JOURNAL_FORMAT_MAX
) {
1018 dout(0) << "Journal " << jp
.front
<< " is in unknown format " << front_journal
->get_stream_format()
1019 << ", does this MDS daemon require upgrade?" << dendl
;
1021 Mutex::Locker
l(mds
->mds_lock
);
1022 if (mds
->is_daemon_stopping()) {
1024 delete front_journal
;
1027 completion
->complete(-EINVAL
);
1029 } else if (mds
->is_standby_replay() || front_journal
->get_stream_format() >= g_conf
->mds_journal_format
) {
1030 /* The journal is of configured format, or we are in standbyreplay and will
1031 * tolerate replaying old journals until we have to go active. Use front_journal as
1032 * our journaler attribute and complete */
1033 dout(4) << "Recovered journal " << jp
.front
<< " in format " << front_journal
->get_stream_format() << dendl
;
1034 journaler
->set_write_error_handler(new C_MDL_WriteError(this));
1036 Mutex::Locker
l(mds
->mds_lock
);
1037 if (mds
->is_daemon_stopping()) {
1040 completion
->complete(0);
1043 /* Hand off to reformat routine, which will ultimately set the
1044 * completion when it has done its thing */
1045 dout(1) << "Journal " << jp
.front
<< " has old format "
1046 << front_journal
->get_stream_format() << ", it will now be updated" << dendl
;
1047 _reformat_journal(jp
, front_journal
, completion
);
1052 * Blocking rewrite of the journal to a new file, followed by
1053 * swap of journal pointer to point to the new one.
1055 * We write the new journal to the 'back' journal from the JournalPointer,
1056 * swapping pointers to make that one the front journal only when we have
1059 void MDLog::_reformat_journal(JournalPointer
const &jp_in
, Journaler
*old_journal
, MDSInternalContextBase
*completion
)
1061 assert(!jp_in
.is_null());
1062 assert(completion
!= NULL
);
1063 assert(old_journal
!= NULL
);
1065 JournalPointer jp
= jp_in
;
1067 /* Set JournalPointer.back to the location we will write the new journal */
1068 inodeno_t primary_ino
= MDS_INO_LOG_OFFSET
+ mds
->get_nodeid();
1069 inodeno_t secondary_ino
= MDS_INO_LOG_BACKUP_OFFSET
+ mds
->get_nodeid();
1070 jp
.back
= (jp
.front
== primary_ino
? secondary_ino
: primary_ino
);
1071 int write_result
= jp
.save(mds
->objecter
);
1072 assert(write_result
== 0);
1074 /* Create the new Journaler file */
1075 Journaler
*new_journal
= new Journaler("mdlog", jp
.back
,
1076 mds
->mdsmap
->get_metadata_pool(), CEPH_FS_ONDISK_MAGIC
, mds
->objecter
, logger
, l_mdl_jlat
, mds
->finisher
);
1077 dout(4) << "Writing new journal header " << jp
.back
<< dendl
;
1078 file_layout_t new_layout
= old_journal
->get_layout();
1079 new_journal
->set_writeable();
1080 new_journal
->create(&new_layout
, g_conf
->mds_journal_format
);
1082 /* Write the new journal header to RADOS */
1083 C_SaferCond write_head_wait
;
1084 new_journal
->write_head(&write_head_wait
);
1085 write_head_wait
.wait();
1087 // Read in the old journal, and whenever we have readable events,
1088 // write them to the new journal.
1091 // In old format journals before event_seq was introduced, the serialized
1092 // offset of a SubtreeMap message in the log is used as the unique ID for
1093 // a log segment. Because we change serialization, this will end up changing
1094 // for us, so we have to explicitly update the fields that point back to that
1096 std::map
<log_segment_seq_t
, log_segment_seq_t
> segment_pos_rewrite
;
1098 // The logic in here borrowed from replay_thread expects mds_lock to be held,
1099 // e.g. between checking readable and doing wait_for_readable so that journaler
1100 // state doesn't change in between.
1101 uint32_t events_transcribed
= 0;
1103 while (!old_journal
->is_readable() &&
1104 old_journal
->get_read_pos() < old_journal
->get_write_pos() &&
1105 !old_journal
->get_error()) {
1107 // Issue a journal prefetch
1108 C_SaferCond readable_waiter
;
1109 old_journal
->wait_for_readable(&readable_waiter
);
1111 // Wait for a journal prefetch to complete
1112 readable_waiter
.wait();
1114 if (old_journal
->get_error()) {
1115 r
= old_journal
->get_error();
1116 dout(0) << "_replay journaler got error " << r
<< ", aborting" << dendl
;
1120 if (!old_journal
->is_readable() &&
1121 old_journal
->get_read_pos() == old_journal
->get_write_pos())
1124 // Read one serialized LogEvent
1125 assert(old_journal
->is_readable());
1127 uint64_t le_pos
= old_journal
->get_read_pos();
1128 bool r
= old_journal
->try_read_entry(bl
);
1129 if (!r
&& old_journal
->get_error())
1133 // Update segment_pos_rewrite
1134 LogEvent
*le
= LogEvent::decode(bl
);
1136 bool modified
= false;
1138 if (le
->get_type() == EVENT_SUBTREEMAP
||
1139 le
->get_type() == EVENT_RESETJOURNAL
) {
1140 ESubtreeMap
*sle
= dynamic_cast<ESubtreeMap
*>(le
);
1141 if (sle
== NULL
|| sle
->event_seq
== 0) {
1142 // A non-explicit event seq: the effective sequence number
1143 // of this segment is it's position in the old journal and
1144 // the new effective sequence number will be its position
1145 // in the new journal.
1146 segment_pos_rewrite
[le_pos
] = new_journal
->get_write_pos();
1147 dout(20) << __func__
<< " discovered segment seq mapping "
1148 << le_pos
<< " -> " << new_journal
->get_write_pos() << dendl
;
1154 // Rewrite segment references if necessary
1155 EMetaBlob
*blob
= le
->get_metablob();
1157 modified
= blob
->rewrite_truncate_finish(mds
, segment_pos_rewrite
);
1160 // Zero-out expire_pos in subtreemap because offsets have changed
1161 // (expire_pos is just an optimization so it's safe to eliminate it)
1162 if (le
->get_type() == EVENT_SUBTREEMAP
1163 || le
->get_type() == EVENT_SUBTREEMAP_TEST
) {
1164 ESubtreeMap
*sle
= dynamic_cast<ESubtreeMap
*>(le
);
1165 assert(sle
!= NULL
);
1166 dout(20) << __func__
<< " zeroing expire_pos in subtreemap event at "
1167 << le_pos
<< " seq=" << sle
->event_seq
<< dendl
;
1168 sle
->expire_pos
= 0;
1174 le
->encode_with_header(bl
, mds
->mdsmap
->get_up_features());
1179 // Failure from LogEvent::decode, our job is to change the journal wrapper,
1180 // not validate the contents, so pass it through.
1181 dout(1) << __func__
<< " transcribing un-decodable LogEvent at old position "
1182 << old_journal
->get_read_pos() << ", new position " << new_journal
->get_write_pos()
1186 // Write (buffered, synchronous) one serialized LogEvent
1187 events_transcribed
+= 1;
1188 new_journal
->append_entry(bl
);
1191 dout(1) << "Transcribed " << events_transcribed
<< " events, flushing new journal" << dendl
;
1192 C_SaferCond flush_waiter
;
1193 new_journal
->flush(&flush_waiter
);
1194 flush_waiter
.wait();
1196 // If failed to rewrite journal, leave the part written journal
1197 // as garbage to be cleaned up next startup.
1200 /* Now that the new journal is safe, we can flip the pointers */
1201 inodeno_t
const tmp
= jp
.front
;
1204 write_result
= jp
.save(mds
->objecter
);
1205 assert(write_result
== 0);
1207 /* Delete the old journal to free space */
1208 dout(1) << "New journal flushed, erasing old journal" << dendl
;
1209 C_SaferCond erase_waiter
;
1210 old_journal
->erase(&erase_waiter
);
1211 int erase_result
= erase_waiter
.wait();
1212 assert(erase_result
== 0);
1214 Mutex::Locker
l(mds
->mds_lock
);
1215 if (mds
->is_daemon_stopping()) {
1219 assert(journaler
== old_journal
);
1224 /* Update the pointer to reflect we're back in clean single journal state. */
1226 write_result
= jp
.save(mds
->objecter
);
1227 assert(write_result
== 0);
1229 /* Reset the Journaler object to its default state */
1230 dout(1) << "Journal rewrite complete, continuing with normal startup" << dendl
;
1232 Mutex::Locker
l(mds
->mds_lock
);
1233 if (mds
->is_daemon_stopping()) {
1237 journaler
= new_journal
;
1238 journaler
->set_readonly();
1239 journaler
->set_write_error_handler(new C_MDL_WriteError(this));
1242 /* Trigger completion */
1244 Mutex::Locker
l(mds
->mds_lock
);
1245 if (mds
->is_daemon_stopping()) {
1248 completion
->complete(0);
1253 // i am a separate thread
1254 void MDLog::_replay_thread()
1256 dout(10) << "_replay_thread start" << dendl
;
1262 while (!journaler
->is_readable() &&
1263 journaler
->get_read_pos() < journaler
->get_write_pos() &&
1264 !journaler
->get_error()) {
1265 C_SaferCond readable_waiter
;
1266 journaler
->wait_for_readable(&readable_waiter
);
1267 r
= readable_waiter
.wait();
1269 if (journaler
->get_error()) {
1270 r
= journaler
->get_error();
1271 dout(0) << "_replay journaler got error " << r
<< ", aborting" << dendl
;
1273 if (mds
->is_standby_replay()) {
1274 // journal has been trimmed by somebody else
1277 mds
->clog
->error() << "missing journal object";
1278 mds
->damaged_unlocked();
1279 ceph_abort(); // Should be unreachable because damaged() calls respawn()
1281 } else if (r
== -EINVAL
) {
1282 if (journaler
->get_read_pos() < journaler
->get_expire_pos()) {
1283 // this should only happen if you're following somebody else
1284 if(journaler
->is_readonly()) {
1285 dout(0) << "expire_pos is higher than read_pos, returning EAGAIN" << dendl
;
1288 mds
->clog
->error() << "invalid journaler offsets";
1289 mds
->damaged_unlocked();
1290 ceph_abort(); // Should be unreachable because damaged() calls respawn()
1293 /* re-read head and check it
1294 * Given that replay happens in a separate thread and
1295 * the MDS is going to either shut down or restart when
1296 * we return this error, doing it synchronously is fine
1297 * -- as long as we drop the main mds lock--. */
1298 C_SaferCond reread_fin
;
1299 journaler
->reread_head(&reread_fin
);
1300 int err
= reread_fin
.wait();
1302 if (err
== -ENOENT
&& mds
->is_standby_replay()) {
1304 dout(1) << "Journal header went away while in standby replay, journal rewritten?"
1308 dout(0) << "got error while reading head: " << cpp_strerror(err
)
1311 mds
->clog
->error() << "error reading journal header";
1312 mds
->damaged_unlocked();
1313 ceph_abort(); // Should be unreachable because damaged() calls
1317 standby_trim_segments();
1318 if (journaler
->get_read_pos() < journaler
->get_expire_pos()) {
1319 dout(0) << "expire_pos is higher than read_pos, returning EAGAIN" << dendl
;
1327 if (!journaler
->is_readable() &&
1328 journaler
->get_read_pos() == journaler
->get_write_pos())
1331 assert(journaler
->is_readable() || mds
->is_daemon_stopping());
1334 uint64_t pos
= journaler
->get_read_pos();
1336 bool r
= journaler
->try_read_entry(bl
);
1337 if (!r
&& journaler
->get_error())
1342 LogEvent
*le
= LogEvent::decode(bl
);
1344 dout(0) << "_replay " << pos
<< "~" << bl
.length() << " / " << journaler
->get_write_pos()
1345 << " -- unable to decode event" << dendl
;
1346 dout(0) << "dump of unknown or corrupt event:\n";
1350 mds
->clog
->error() << "corrupt journal event at " << pos
<< "~"
1351 << bl
.length() << " / "
1352 << journaler
->get_write_pos();
1353 if (g_conf
->mds_log_skip_corrupt_events
) {
1356 mds
->damaged_unlocked();
1357 ceph_abort(); // Should be unreachable because damaged() calls
1362 le
->set_start_off(pos
);
1365 if (le
->get_type() == EVENT_SUBTREEMAP
||
1366 le
->get_type() == EVENT_RESETJOURNAL
) {
1367 ESubtreeMap
*sle
= dynamic_cast<ESubtreeMap
*>(le
);
1368 if (sle
&& sle
->event_seq
> 0)
1369 event_seq
= sle
->event_seq
;
1372 segments
[event_seq
] = new LogSegment(event_seq
, pos
);
1373 logger
->set(l_mdl_seg
, segments
.size());
1378 // have we seen an import map yet?
1379 if (segments
.empty()) {
1380 dout(10) << "_replay " << pos
<< "~" << bl
.length() << " / " << journaler
->get_write_pos()
1381 << " " << le
->get_stamp() << " -- waiting for subtree_map. (skipping " << *le
<< ")" << dendl
;
1383 dout(10) << "_replay " << pos
<< "~" << bl
.length() << " / " << journaler
->get_write_pos()
1384 << " " << le
->get_stamp() << ": " << *le
<< dendl
;
1385 le
->_segment
= get_current_segment(); // replay may need this
1386 le
->_segment
->num_events
++;
1387 le
->_segment
->end
= journaler
->get_read_pos();
1391 Mutex::Locker
l(mds
->mds_lock
);
1392 if (mds
->is_daemon_stopping()) {
1395 logger
->inc(l_mdl_replayed
);
1401 logger
->set(l_mdl_rdpos
, pos
);
1406 assert(journaler
->get_read_pos() == journaler
->get_write_pos());
1407 dout(10) << "_replay - complete, " << num_events
1408 << " events" << dendl
;
1410 logger
->set(l_mdl_expos
, journaler
->get_expire_pos());
1413 safe_pos
= journaler
->get_write_safe_pos();
1415 dout(10) << "_replay_thread kicking waiters" << dendl
;
1417 Mutex::Locker
l(mds
->mds_lock
);
1418 if (mds
->is_daemon_stopping()) {
1421 finish_contexts(g_ceph_context
, waitfor_replay
, r
);
1424 dout(10) << "_replay_thread finish" << dendl
;
1427 void MDLog::standby_trim_segments()
1429 dout(10) << "standby_trim_segments" << dendl
;
1430 uint64_t expire_pos
= journaler
->get_expire_pos();
1431 dout(10) << " expire_pos=" << expire_pos
<< dendl
;
1432 bool removed_segment
= false;
1433 while (have_any_segments()) {
1434 LogSegment
*seg
= get_oldest_segment();
1435 dout(10) << " segment seq=" << seg
->seq
<< " " << seg
->offset
<<
1436 "~" << seg
->end
- seg
->offset
<< dendl
;
1438 if (seg
->end
> expire_pos
) {
1439 dout(10) << " won't remove, not expired!" << dendl
;
1443 if (segments
.size() == 1) {
1444 dout(10) << " won't remove, last segment!" << dendl
;
1448 dout(10) << " removing segment" << dendl
;
1449 mds
->mdcache
->standby_trim_segment(seg
);
1450 remove_oldest_segment();
1451 removed_segment
= true;
1454 if (removed_segment
) {
1455 dout(20) << " calling mdcache->trim!" << dendl
;
1456 mds
->mdcache
->trim();
1458 dout(20) << " removed no segments!" << dendl
;
1462 void MDLog::dump_replay_status(Formatter
*f
) const
1464 f
->open_object_section("replay_status");
1465 f
->dump_unsigned("journal_read_pos", journaler
? journaler
->get_read_pos() : 0);
1466 f
->dump_unsigned("journal_write_pos", journaler
? journaler
->get_write_pos() : 0);
1467 f
->dump_unsigned("journal_expire_pos", journaler
? journaler
->get_expire_pos() : 0);
1468 f
->dump_unsigned("num_events", get_num_events());
1469 f
->dump_unsigned("num_segments", get_num_segments());