Rate limit certain warning messages
There are a few warning messages that can easily flood the log, making it more difficult to figure out what causes the problem. Those are - too long WAL write - waited for ... bytes of vinyl memory quota for too long - get/select(...) => ... took too long - readahead limit is reached - net_msg_max limit is reached Actually, it's pointless to print each and every of them, because all messages of the same kind are similar and don't convey any additional information. So this patch limits the rate at which those messages may be printed. To achieve that, it introduces say_ratelimited() helper, which works exactly like say() except it does nothing if too many messages of the same kind have already been printed in the last few seconds. The implementation is trivial - say_ratelimited() defines a static ratelimit state variable at its call site (it's a macro) and checks it before logging anything. If the ratelimit state says that an event may be emitted, it will log the message, otherwise it will skip it and eventually print the total number of skipped messages instead. The rate limit is set to 10 messages per 5 seconds for each kind of a warning message enumerated above. Here's how it looks in the log: 2018-12-11 18:07:21.830 [30404] iproto iproto.cc:524 W> stopping input on connection fd 15, aka 127.0.0.1:12345, peer of 127.0.0.1:59212, readahead limit is reached 2018-12-11 18:07:21.831 [30404] iproto iproto.cc:524 W> stopping input on connection fd 15, aka 127.0.0.1:12345, peer of 127.0.0.1:59212, readahead limit is reached 2018-12-11 18:07:21.831 [30404] iproto iproto.cc:524 W> stopping input on connection fd 15, aka 127.0.0.1:12345, peer of 127.0.0.1:59212, readahead limit is reached 2018-12-11 18:07:21.831 [30404] iproto iproto.cc:524 W> stopping input on connection fd 15, aka 127.0.0.1:12345, peer of 127.0.0.1:59212, readahead limit is reached 2018-12-11 18:07:21.831 [30404] iproto iproto.cc:524 W> stopping input on connection fd 15, aka 127.0.0.1:12345, peer of 127.0.0.1:59212, readahead limit is reached 2018-12-11 18:07:21.832 [30404] iproto iproto.cc:524 W> stopping input on connection fd 15, aka 127.0.0.1:12345, peer of 127.0.0.1:59212, readahead limit is reached 2018-12-11 18:07:21.832 [30404] iproto iproto.cc:524 W> stopping input on connection fd 15, aka 127.0.0.1:12345, peer of 127.0.0.1:59212, readahead limit is reached 2018-12-11 18:07:21.832 [30404] iproto iproto.cc:524 W> stopping input on connection fd 15, aka 127.0.0.1:12345, peer of 127.0.0.1:59212, readahead limit is reached 2018-12-11 18:07:21.832 [30404] iproto iproto.cc:524 W> stopping input on connection fd 15, aka 127.0.0.1:12345, peer of 127.0.0.1:59212, readahead limit is reached 2018-12-11 18:07:21.832 [30404] iproto iproto.cc:524 W> stopping input on connection fd 15, aka 127.0.0.1:12345, peer of 127.0.0.1:59212, readahead limit is reached 2018-12-11 18:07:26.851 [30404] iproto iproto.cc:524 W> 9635 messages suppressed Closes #2218
Showing
- src/box/iproto.cc 6 additions, 4 deletionssrc/box/iproto.cc
- src/box/txn.c 3 additions, 2 deletionssrc/box/txn.c
- src/box/vy_point_lookup.c 4 additions, 3 deletionssrc/box/vy_point_lookup.c
- src/box/vy_quota.c 3 additions, 2 deletionssrc/box/vy_quota.c
- src/box/vy_read_iterator.c 5 additions, 4 deletionssrc/box/vy_read_iterator.c
- src/say.h 38 additions, 0 deletionssrc/say.h
Loading
Please register or sign in to comment