RE: Mon gets flooded with log messages for default log level

RE: Mon gets flooded with log messages for default log level

[Aanchal Agrawal]

Any help on this ...

-----Original Message-----
From: Aanchal Agrawal
Sent: Friday, September 05, 2014 5:56 PM
To: ceph-devel@vger.kernel.org
Subject: Mon gets flooded with log messages for default log level

Hi,

With reference to commit f7d1902ccf9d5bb97cda626d718c3bb02f991a6d, 'Paxos' default level has been increased to 1.
This cause mon to get flooded with the following message,  thus causes OS Drive(160GB) to get filled in 4-5 hours.

Log Snippet ::
==================
2014-09-01 16:35:11.527734 7f7efe706700 1 mon.rack6-ramp-1@0(leader).paxos(paxos active c 1..712) is_readable now=2014-09-01 16:35:11.527735 lease_expire=2014-09-01 16:35:13.637940 has v0 lc 712
2014-09-01 16:35:11.527773 7f7efe706700 1 mon.rack6-ramp-1@0(leader).paxos(paxos active c 1..712) is_readable now=2014-09-01 16:35:11.527774 lease_expire=2014-09-01 16:35:13.637940 has v0 lc 712
2014-09-01 16:35:11.527807 7f7efe706700 1 mon.rack6-ramp-1@0(leader).paxos(paxos active c 1..712) is_readable now=2014-09-01 16:35:11.527807 lease_expire=2014-09-01 16:35:13.637940 has v0 lc 712
2014-09-01 16:35:11.527840 7f7efe706700 1 mon.rack6-ramp-1@0(leader).paxos(paxos active c 1..712) is_readable now=2014-09-01 16:35:11.527840 lease_expire=2014-09-01 16:35:13.637940 has v0 lc 712
2014-09-01 16:35:11.527874 7f7efe706700 1 mon.rack6-ramp-1@0(leader).paxos(paxos active c 1..712) is_readable now=2014-09-01 16:35:11.527875 lease_expire=2014-09-01 16:35:13.637940 has v0 lc 712 ==================

==================
src/mon/Paxos.cc
dout(1) << "is_readable now=" << ceph_clock_now(g_ceph_context) << " lease_expire=" << lease_expire
          << " has v" << v << " lc " << last_committed << dendl; ==================

Incrementing 'log level' of this message to 2 or something else will solve this problem of mon space getting full quickly.

Moreover is this message that useful to get printed with default debug level '1'?
Let me know if I am missing something here.

Thanks,
Aanchal

________________________________

PLEASE NOTE: The information contained in this electronic mail message is intended only for the use of the designated recipient(s) named above. If the reader of this message is not the intended recipient, you are hereby notified that you have received this message in error and that any review, dissemination, distribution, or copying of this message is strictly prohibited. If you have received this communication in error, please notify the sender by telephone or e-mail (as shown above) immediately and destroy any and all copies of this message in your possession (whether hard copies or electronically stored copies).

RE: Mon gets flooded with log messages for default log level

[Sage Weil]

Note that you can make these messages stop with

  debug mon = 0

in your ceph.conf.  It looks like you are right, though: that 
is_readable() dout line is spamming things.  We can fix that in the next 
release.

	https://github.com/ceph/ceph/pull/2421

Thanks!
sage


On Mon, 8 Sep 2014, Aanchal Agrawal wrote:

> Any help on this ...
> 
> -----Original Message-----
> From: Aanchal Agrawal
> Sent: Friday, September 05, 2014 5:56 PM
> To: ceph-devel@vger.kernel.org
> Subject: Mon gets flooded with log messages for default log level
> 
> Hi,
> 
> With reference to commit f7d1902ccf9d5bb97cda626d718c3bb02f991a6d, 'Paxos' default level has been increased to 1.
> This cause mon to get flooded with the following message,  thus causes OS Drive(160GB) to get filled in 4-5 hours.
> 
> Log Snippet ::
> ==================
> 2014-09-01 16:35:11.527734 7f7efe706700 1 mon.rack6-ramp-1@0(leader).paxos(paxos active c 1..712) is_readable now=2014-09-01 16:35:11.527735 lease_expire=2014-09-01 16:35:13.637940 has v0 lc 712
> 2014-09-01 16:35:11.527773 7f7efe706700 1 mon.rack6-ramp-1@0(leader).paxos(paxos active c 1..712) is_readable now=2014-09-01 16:35:11.527774 lease_expire=2014-09-01 16:35:13.637940 has v0 lc 712
> 2014-09-01 16:35:11.527807 7f7efe706700 1 mon.rack6-ramp-1@0(leader).paxos(paxos active c 1..712) is_readable now=2014-09-01 16:35:11.527807 lease_expire=2014-09-01 16:35:13.637940 has v0 lc 712
> 2014-09-01 16:35:11.527840 7f7efe706700 1 mon.rack6-ramp-1@0(leader).paxos(paxos active c 1..712) is_readable now=2014-09-01 16:35:11.527840 lease_expire=2014-09-01 16:35:13.637940 has v0 lc 712
> 2014-09-01 16:35:11.527874 7f7efe706700 1 mon.rack6-ramp-1@0(leader).paxos(paxos active c 1..712) is_readable now=2014-09-01 16:35:11.527875 lease_expire=2014-09-01 16:35:13.637940 has v0 lc 712 ==================
> 
> ==================
> src/mon/Paxos.cc
> dout(1) << "is_readable now=" << ceph_clock_now(g_ceph_context) << " lease_expire=" << lease_expire
>           << " has v" << v << " lc " << last_committed << dendl; ==================
> 
> Incrementing 'log level' of this message to 2 or something else will solve this problem of mon space getting full quickly.
> 
> Moreover is this message that useful to get printed with default debug level '1'?
> Let me know if I am missing something here.
> 
> Thanks,
> Aanchal
> 
> ________________________________
> 
> PLEASE NOTE: The information contained in this electronic mail message is intended only for the use of the designated recipient(s) named above. If the reader of this message is not the intended recipient, you are hereby notified that you have received this message in error and that any review, dissemination, distribution, or copying of this message is strictly prohibited. If you have received this communication in error, please notify the sender by telephone or e-mail (as shown above) immediately and destroy any and all copies of this message in your possession (whether hard copies or electronically stored copies).
> 
> --
> To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> 
> 

RE: Mon gets flooded with log messages for default log level

[Somnath Roy]

But, Sage, it is not happening all the time. For some reason, in some cases it is waiting for the maps to be readable. Could you please let us know why it can happen in some scenario ?
By not dumping this unusual scenario , will we be missing anything ?

Thanks & Regards
Somnath

-----Original Message-----
From: ceph-devel-owner@vger.kernel.org [mailto:ceph-devel-owner@vger.kernel.org] On Behalf Of Sage Weil
Sent: Monday, September 08, 2014 6:59 AM
To: Aanchal Agrawal
Cc: ceph-devel@vger.kernel.org; Gregory Farnum; Joao Eduardo Luis
Subject: RE: Mon gets flooded with log messages for default log level

Note that you can make these messages stop with

  debug mon = 0

in your ceph.conf.  It looks like you are right, though: that
is_readable() dout line is spamming things.  We can fix that in the next release.

	https://github.com/ceph/ceph/pull/2421

Thanks!
sage


On Mon, 8 Sep 2014, Aanchal Agrawal wrote:

> Any help on this ...
> 
> -----Original Message-----
> From: Aanchal Agrawal
> Sent: Friday, September 05, 2014 5:56 PM
> To: ceph-devel@vger.kernel.org
> Subject: Mon gets flooded with log messages for default log level
> 
> Hi,
> 
> With reference to commit f7d1902ccf9d5bb97cda626d718c3bb02f991a6d, 'Paxos' default level has been increased to 1.
> This cause mon to get flooded with the following message,  thus causes OS Drive(160GB) to get filled in 4-5 hours.
> 
> Log Snippet ::
> ==================
> 2014-09-01 16:35:11.527734 7f7efe706700 1 
> mon.rack6-ramp-1@0(leader).paxos(paxos active c 1..712) is_readable 
> now=2014-09-01 16:35:11.527735 lease_expire=2014-09-01 16:35:13.637940 
> has v0 lc 712
> 2014-09-01 16:35:11.527773 7f7efe706700 1 
> mon.rack6-ramp-1@0(leader).paxos(paxos active c 1..712) is_readable 
> now=2014-09-01 16:35:11.527774 lease_expire=2014-09-01 16:35:13.637940 
> has v0 lc 712
> 2014-09-01 16:35:11.527807 7f7efe706700 1 
> mon.rack6-ramp-1@0(leader).paxos(paxos active c 1..712) is_readable 
> now=2014-09-01 16:35:11.527807 lease_expire=2014-09-01 16:35:13.637940 
> has v0 lc 712
> 2014-09-01 16:35:11.527840 7f7efe706700 1 
> mon.rack6-ramp-1@0(leader).paxos(paxos active c 1..712) is_readable 
> now=2014-09-01 16:35:11.527840 lease_expire=2014-09-01 16:35:13.637940 
> has v0 lc 712
> 2014-09-01 16:35:11.527874 7f7efe706700 1 
> mon.rack6-ramp-1@0(leader).paxos(paxos active c 1..712) is_readable 
> now=2014-09-01 16:35:11.527875 lease_expire=2014-09-01 16:35:13.637940 
> has v0 lc 712 ==================
> 
> ==================
> src/mon/Paxos.cc
> dout(1) << "is_readable now=" << ceph_clock_now(g_ceph_context) << " lease_expire=" << lease_expire
>           << " has v" << v << " lc " << last_committed << dendl; 
> ==================
> 
> Incrementing 'log level' of this message to 2 or something else will solve this problem of mon space getting full quickly.
> 
> Moreover is this message that useful to get printed with default debug level '1'?
> Let me know if I am missing something here.
> 
> Thanks,
> Aanchal
> 
> ________________________________
> 
> PLEASE NOTE: The information contained in this electronic mail message is intended only for the use of the designated recipient(s) named above. If the reader of this message is not the intended recipient, you are hereby notified that you have received this message in error and that any review, dissemination, distribution, or copying of this message is strictly prohibited. If you have received this communication in error, please notify the sender by telephone or e-mail (as shown above) immediately and destroy any and all copies of this message in your possession (whether hard copies or electronically stored copies).
> 
> --
> To unsubscribe from this list: send the line "unsubscribe ceph-devel" 
> in the body of a message to majordomo@vger.kernel.org More majordomo 
> info at  http://vger.kernel.org/majordomo-info.html
> 
> 
--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in the body of a message to majordomo@vger.kernel.org More majordomo info at  http://vger.kernel.org/majordomo-info.html

RE: Mon gets flooded with log messages for default log level

[Sage Weil]

Hi Somnath,

On Mon, 8 Sep 2014, Somnath Roy wrote:
> But, Sage, it is not happening all the time. For some reason, in some 
> cases it is waiting for the maps to be readable. Could you please let us 
> know why it can happen in some scenario ? By not dumping this unusual 
> scenario , will we be missing anything ?

The is_readable method is called from a bunch of different contexts.. 
generally when a message is received or when a previously received 
and queued message gets reexamined after an election or paxos round.

In either case, I think you're right that dout(1) is overkill; we've 
changed it to 5.  It is useful for debugging, but level 5 should be just 
fine I think.

sage


> 
> Thanks & Regards
> Somnath
> 
> -----Original Message-----
> From: ceph-devel-owner@vger.kernel.org [mailto:ceph-devel-owner@vger.kernel.org] On Behalf Of Sage Weil
> Sent: Monday, September 08, 2014 6:59 AM
> To: Aanchal Agrawal
> Cc: ceph-devel@vger.kernel.org; Gregory Farnum; Joao Eduardo Luis
> Subject: RE: Mon gets flooded with log messages for default log level
> 
> Note that you can make these messages stop with
> 
>   debug mon = 0
> 
> in your ceph.conf.  It looks like you are right, though: that
> is_readable() dout line is spamming things.  We can fix that in the next release.
> 
> 	https://github.com/ceph/ceph/pull/2421
> 
> Thanks!
> sage
> 
> 
> On Mon, 8 Sep 2014, Aanchal Agrawal wrote:
> 
> > Any help on this ...
> > 
> > -----Original Message-----
> > From: Aanchal Agrawal
> > Sent: Friday, September 05, 2014 5:56 PM
> > To: ceph-devel@vger.kernel.org
> > Subject: Mon gets flooded with log messages for default log level
> > 
> > Hi,
> > 
> > With reference to commit f7d1902ccf9d5bb97cda626d718c3bb02f991a6d, 'Paxos' default level has been increased to 1.
> > This cause mon to get flooded with the following message,  thus causes OS Drive(160GB) to get filled in 4-5 hours.
> > 
> > Log Snippet ::
> > ==================
> > 2014-09-01 16:35:11.527734 7f7efe706700 1 
> > mon.rack6-ramp-1@0(leader).paxos(paxos active c 1..712) is_readable 
> > now=2014-09-01 16:35:11.527735 lease_expire=2014-09-01 16:35:13.637940 
> > has v0 lc 712
> > 2014-09-01 16:35:11.527773 7f7efe706700 1 
> > mon.rack6-ramp-1@0(leader).paxos(paxos active c 1..712) is_readable 
> > now=2014-09-01 16:35:11.527774 lease_expire=2014-09-01 16:35:13.637940 
> > has v0 lc 712
> > 2014-09-01 16:35:11.527807 7f7efe706700 1 
> > mon.rack6-ramp-1@0(leader).paxos(paxos active c 1..712) is_readable 
> > now=2014-09-01 16:35:11.527807 lease_expire=2014-09-01 16:35:13.637940 
> > has v0 lc 712
> > 2014-09-01 16:35:11.527840 7f7efe706700 1 
> > mon.rack6-ramp-1@0(leader).paxos(paxos active c 1..712) is_readable 
> > now=2014-09-01 16:35:11.527840 lease_expire=2014-09-01 16:35:13.637940 
> > has v0 lc 712
> > 2014-09-01 16:35:11.527874 7f7efe706700 1 
> > mon.rack6-ramp-1@0(leader).paxos(paxos active c 1..712) is_readable 
> > now=2014-09-01 16:35:11.527875 lease_expire=2014-09-01 16:35:13.637940 
> > has v0 lc 712 ==================
> > 
> > ==================
> > src/mon/Paxos.cc
> > dout(1) << "is_readable now=" << ceph_clock_now(g_ceph_context) << " lease_expire=" << lease_expire
> >           << " has v" << v << " lc " << last_committed << dendl; 
> > ==================
> > 
> > Incrementing 'log level' of this message to 2 or something else will solve this problem of mon space getting full quickly.
> > 
> > Moreover is this message that useful to get printed with default debug level '1'?
> > Let me know if I am missing something here.
> > 
> > Thanks,
> > Aanchal
> > 
> > ________________________________
> > 
> > PLEASE NOTE: The information contained in this electronic mail message is intended only for the use of the designated recipient(s) named above. If the reader of this message is not the intended recipient, you are hereby notified that you have received this message in error and that any review, dissemination, distribution, or copying of this message is strictly prohibited. If you have received this communication in error, please notify the sender by telephone or e-mail (as shown above) immediately and destroy any and all copies of this message in your possession (whether hard copies or electronically stored copies).
> > 
> > --
> > To unsubscribe from this list: send the line "unsubscribe ceph-devel" 
> > in the body of a message to majordomo@vger.kernel.org More majordomo 
> > info at  http://vger.kernel.org/majordomo-info.html
> > 
> > 
> --
> To unsubscribe from this list: send the line "unsubscribe ceph-devel" in the body of a message to majordomo@vger.kernel.org More majordomo info at  http://vger.kernel.org/majordomo-info.html
> --
> To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> 
> 

Mon gets flooded with log messages for default log level

[Aanchal Agrawal]

Hi,

With reference to commit f7d1902ccf9d5bb97cda626d718c3bb02f991a6d, 'Paxos' default level has been increased to 1.
This cause mon to get flooded with the following message,  thus causes OS Drive(160GB) to get filled in 4-5 hours.

Log Snippet ::
==================
2014-09-01 16:35:11.527734 7f7efe706700 1 mon.rack6-ramp-1@0(leader).paxos(paxos active c 1..712) is_readable now=2014-09-01 16:35:11.527735 lease_expire=2014-09-01 16:35:13.637940 has v0 lc 712
2014-09-01 16:35:11.527773 7f7efe706700 1 mon.rack6-ramp-1@0(leader).paxos(paxos active c 1..712) is_readable now=2014-09-01 16:35:11.527774 lease_expire=2014-09-01 16:35:13.637940 has v0 lc 712
2014-09-01 16:35:11.527807 7f7efe706700 1 mon.rack6-ramp-1@0(leader).paxos(paxos active c 1..712) is_readable now=2014-09-01 16:35:11.527807 lease_expire=2014-09-01 16:35:13.637940 has v0 lc 712
2014-09-01 16:35:11.527840 7f7efe706700 1 mon.rack6-ramp-1@0(leader).paxos(paxos active c 1..712) is_readable now=2014-09-01 16:35:11.527840 lease_expire=2014-09-01 16:35:13.637940 has v0 lc 712
2014-09-01 16:35:11.527874 7f7efe706700 1 mon.rack6-ramp-1@0(leader).paxos(paxos active c 1..712) is_readable now=2014-09-01 16:35:11.527875 lease_expire=2014-09-01 16:35:13.637940 has v0 lc 712
==================

==================
src/mon/Paxos.cc
dout(1) << "is_readable now=" << ceph_clock_now(g_ceph_context) << " lease_expire=" << lease_expire
          << " has v" << v << " lc " << last_committed << dendl;
==================

Incrementing 'log level' of this message to 2 or something else will solve this problem of mon space getting full quickly.

Moreover is this message that useful to get printed with default debug level '1'?
Let me know if I am missing something here.

Thanks,
Aanchal

________________________________

PLEASE NOTE: The information contained in this electronic mail message is intended only for the use of the designated recipient(s) named above. If the reader of this message is not the intended recipient, you are hereby notified that you have received this message in error and that any review, dissemination, distribution, or copying of this message is strictly prohibited. If you have received this communication in error, please notify the sender by telephone or e-mail (as shown above) immediately and destroy any and all copies of this message in your possession (whether hard copies or electronically stored copies).