Feat[MQB]: Enhance queue consumption monitor alarm log with additional details #420

alexander-e1off · 2024-09-13T13:17:29Z

When a queue starts to fill up, it is valuable to see information about which AppIds are impacted, and information about the messages in the queue.
Especially in the case of subscriptions (which we are enabling for everyone now), messages that match no subscription expression will build up in the put aside list.
To help make this situation clearer to operators and users (what apps are impacted, why are messages building up, how old is the head of the queue for each app, etc), we can log more information when the watermark alarm is triggered:

Sizes of put-aside list and redelivery list for each app for that queue;
Oldest message's timestamp in put aside list & its message properties;
Number of unconfirmed messages;
Total size of messages for each app (but seems it is already done by storage()->capacityMeter()->printShortSummary() );

This is to help debug why a message doesn't match a subscription.

Alarm log looks like this:

ERROR mqbblp_rootqueueengine.cpp:1765 ALARM [QUEUE_STUCK] Queue 'bmq://bmq.test.mem.fanout/my1?id=foo' Messages [current: 2 / 1,000], Bytes [current: 110  B / 1.00 MB], max idle time 20.00 s appears to be stuck. It currently has 1 consumers.
  1. bmqtool.tsk:199639@127.0.0.1~localhost:37430
    Handle Parameters .....: [ uri = "bmq://bmq.test.mem.fanout/my1" qId = 0 subIdInfo = NULL flags = 2 readCount = 1 writeCount = 0 adminCount = 0 ]
    Number of unconfirmed messages .....: 1
    UnconfirmedMonitors ....:
   STATE_NORMAL [Messages (STATE_NORMAL): 1 (820 - 820 - 1,024), Bytes (STATE_NORMAL): 55  B (25.60 MB - 25.60 MB - 32.00 MB)]
   STATE_NORMAL [Messages (STATE_NORMAL): 0 (820 - 820 - 1,024), Bytes (STATE_NORMAL): 0  B (25.60 MB - 25.60 MB - 32.00 MB)]

For appId: foo
Put aside list size: 1
Redelivery list size: 0
Number of messages: 2
Number of bytes: 110

Consumer subscription expressions:
x == 2
y == 4
y == 3
x == 1

Oldest message in a 'Put aside' list:
GUID                              Size        Timestamp (UTC)
4000000000033E07AD91F4D9C7E5D709       55  B  24SEP2024_09:09:06.777472+0000
Message Properties: [ sample_str (STRING) = "foo bar" x (INT32) = 10 ]

10 oldest messages in the queue:
Printing 2 message(s) [0-1 / 2] (total: 110  B)
       GUID                              Size        Timestamp (UTC)
    0: 4000000000033E07AD91F4D9C7E5D709       55  B  24SEP2024_09:09:06.777471+0000
    1: 4000010000344E57D5C6F4D9C7E5D709       55  B  24SEP2024_09:12:37.504283+0000

Current head of the queue:
GUID                              Size        Timestamp (UTC)
4000000000033E07AD91F4D9C7E5D709       55  B  24SEP2024_09:09:06.777471+0000

Implementation details:

Log alarm logic is moved from QueueConsumptionMonitor into RootQueueEngine class, where more data is available;
Callback is passed to QueueConsumptionMonitor and called in case of alarm to log alarm data;

Signed-off-by: Aleksandr Ivanov <aivanov71@bloomberg.net>

dorjesinpo

Looks good. Few questions.

Maybe, we can print Storage::numMessages and Storage::numBytes as well?
Can we get rid of QueueEngineUtil_AppState::head() and QueueConsumptionMonitor::SubStreamInfo::d_headCb now?
Is QueueConsumptionMonitor::onTransitionToIdle "level triggered" (vs "edge triggered")? It can be noisy, how often we want that log?

@chrisbeard please take a look at the output

alexander-e1off · 2024-09-16T15:49:53Z

Regarding Maybe, we can print Storage::numMessages and Storage::numBytes as well?. CapacityMeter::printShortSummary() already prints numMessages and numBytes, e.g.

Messages [current: 2 / 1,000], Bytes [current: 66  B / 1.00 MB]

Aren't they the same as Storage::numMessages() and Storage::numBytes? In my test they printed the same values. Are there any possible scenarios when they will differ?

alexander-e1off · 2024-09-16T17:22:02Z

Regarding Can we get rid of QueueEngineUtil_AppState::head() and QueueConsumptionMonitor::SubStreamInfo::d_headCb now? Now we print oldest message from put aside list, but what happens if we have empty put aside list and not empty redelivery list? For example, there are 4 messages, and I limited to print only 3 oldest messages. Without printing head we don't know what is the last message in queue:

ERROR mqbblp_rootqueueengine.cpp:1766 ALARM [QUEUE_STUCK] Queue 'bmq://bmq.test.mem.fanout/my1?id=foo' Messages [current: 4 / 1,000], Bytes [current: 44  B / 1.00 MB], max idle time 20.00 s appears to be stuck. It currently has 0 consumers.

Put aside list size: 0
Redelivery list size: 3

3 oldest messages in the queue:
Printing 3 message(s) [0-2 / 4] (total: 33  B)
       GUID                              Size        Timestamp (UTC)
    0: 400000000011896EDA51C2376057798E       11  B  17SEP2024_12:23:02.458416+0000
    1: 400001000012F52671B0C2376057798E       11  B  17SEP2024_12:23:08.559553+0000
    2: 4000020000132AB6F3D6C2376057798E       11  B  17SEP2024_12:23:09.458243+0000

Current head of the queue:
GUID                              Size        Timestamp (UTC)
40000300001A6876353BC2376057798E       11  B  17SEP2024_12:23:40.559572+0000

Is head info valuable in this scenario?

Regarding Is QueueConsumptionMonitor::onTransitionToIdle "level triggered" (vs "edge triggered")? - QueueConsumptionMonitor::onTransitionToIdle is edge triggered, so onTransitionToIdle is called only once when state is transitioned from Active to Idle.

dorjesinpo · 2024-09-18T16:31:35Z

QueueConsumptionMonitor::onTransitionToIdle is edge triggered, so onTransitionToIdle is called only once when state is transitioned from Active to Idle.

Ok. This can flap, we often see a lot of subsequent logs. We are increasing the size of what's logged, so we may want to throttle the logging.

Signed-off-by: Aleksandr Ivanov <aivanov71@bloomberg.net>

dorjesinpo

There may be a possibility to reduce mqbblp_queueconsumptionmonitor.t dependencies. Let's explore it.

dorjesinpo · 2024-09-29T16:45:21Z

src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.t.cpp

@@ -503,19 +498,7 @@ TEST_F(Test, putAliveIdleWithConsumer)
    ASSERT_EQ(logObserver.records().size(), ++expectedLogRecords);
    ASSERT(mwctst::ScopedLogObserverUtil::recordMessageMatch(
        logObserver.records().back(),
-        "ALARM \\[QUEUE_CONSUMER_MONITOR\\].*It currently has 2 consumers",


As I understand, there is no "test consumer 1/2" log because it is outside of the QueueConsumptionMonitor now.
That is fine.
Question, maybe we do not need d_consumer1/2 now?
Maybe, the Test can shrink now since the state of monitored objects is factored out by the Test::LoggingCb?
If that is the case, we can remove Test::d_queue, Test::d_queueState, Test::d_domain, Test::d_cluster, and Test::createClient. Possibly, d_storage as well, if Test::putMessage() changes the state of Test instead of the Test::d_storage (is that Test::d_advance?)

Refactored the test by simplifying logic and removing consumers, but still need Test::d_queueState and its dependencies, because it is required for d_monitor.

dorjesinpo · 2024-09-29T17:13:16Z

src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp

+    BSLS_ASSERT_SAFE(d_queueState_p->queue()->dispatcher()->inDispatcherThread(
+        d_queueState_p->queue()));
+
+    // Construct AppId from appKey


You can replace the App lookup code with
Apps::const_iterator cItApp = d_apps.findByKey2(AppKeyCount(appKey, 0));

AppKeyCount is an (hopefully, not for too long) artefact of our transitioning from non-CSL to CSL way of registering Apps. In short, only registered Apps are supposed to have storage and consumption monitoring. And registered Apps should have 0 as the "count" .

Replaced as proposed.

dorjesinpo · 2024-09-29T17:15:57Z

src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp

+    bdlma::LocalSequentialAllocator<4096> localAllocator(d_allocator_p);
+
+    bmqt::Uri uri(&localAllocator);
+    uriBuilder.uri(&uri);


d_queueState_p->uri()

dorjesinpo · 2024-09-29T17:30:26Z

src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp

+        << " consumers." << ss.str() << '\n';
+
+    // Log un-delivered messages info
+    mqbi::Storage* const storage = d_queueState_p->storage();


Use storage or d_queueState_p->storage() everywhere?

Signed-off-by: Aleksandr Ivanov <aivanov71@bloomberg.net>

alexander-e1off · 2024-10-14T12:19:35Z

src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.t.cpp

              QueueConsumptionMonitor::State::e_ALIVE);
    ASSERT_EQ(logObserver.records().size(), expectedLogRecords);
 }

-TEST_F(Test, logFormat)


This test originally tested the log format, but now logging is done by the callback, so this test makes no sense.

alexander-e1off · 2024-10-14T12:22:16Z

src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.t.cpp

@@ -727,122 +497,6 @@ TEST_F(Test, putAliveIdleSendAliveTwoSubstreams)
    ASSERT_EQ(d_monitor.state(key2), QueueConsumptionMonitor::State::e_ALIVE);
 }

-TEST_F(Test, putAliveIdleSendAliveTwoSubstreamsTwoConsumers)


Since consumers are removed, this test becomes the same as above, remove it.

dorjesinpo

Thank you

678098

Some comments

678098 · 2024-10-14T23:22:56Z

src/groups/mqb/mqbblp/mqbblp_rootqueueengine.h

+    /// `enableLog` is `true` it logs alarm data. Return `true` if there are
+    /// un-delivered messages and `false` otherwise.
+    bool logAlarmCb(const mqbu::StorageKey& appKey,
+                    const bool              enableLog) const;


Suggested change

const bool enableLog) const;

bool enableLog) const;

Not necessary to qualify as const for a basic type in arguments

678098 · 2024-10-14T23:26:28Z

src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.cpp

@@ -229,6 +215,7 @@ void QueueConsumptionMonitor::onTimer(bsls::Types::Int64 currentTimer)
    // PRECONDITIONS
    BSLS_ASSERT_SAFE(d_queueState_p->queue()->dispatcher()->inDispatcherThread(
        d_queueState_p->queue()));
+    BSLS_ASSERT_SAFE(d_loggingCb);


Suggested change

BSLS_ASSERT_SAFE(d_loggingCb);

Might remove this precondition since we set this up in the only constructor and check it right there already. We don't have setters or other way to change d_loggingCb to an invalid value

678098 · 2024-10-14T23:29:13Z

src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.h

@@ -210,8 +210,7 @@ class QueueConsumptionMonitor {
        static const char* toAscii(Transition::Enum value);
    };

-    typedef bsl::function<bslma::ManagedPtr<mqbi::StorageIterator>(void)>
-        HeadCb;
+    typedef bsl::function<bool(const mqbu::StorageKey&, bool)> LoggingCb;


Might be good to explain here what the first and the second args mean

678098 · 2024-10-14T23:29:29Z

src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.h

@@ -220,8 +219,7 @@ class QueueConsumptionMonitor {
    struct SubStreamInfo {
        // CREATORS

-        SubStreamInfo(const HeadCb& headCb);
-        SubStreamInfo(const SubStreamInfo& other);
+        SubStreamInfo();


Good simplification

678098 · 2024-10-14T23:32:37Z

src/groups/mqb/mqbblp/mqbblp_queueconsumptionmonitor.h

+    /// Update the specified 'subStreamInfo', associated to the specified
+    /// 'appKey', and write log, upon transition to alive state.


Suggested change

/// Update the specified 'subStreamInfo', associated to the specified

/// 'appKey', and write log, upon transition to alive state.

/// Update the specified `subStreamInfo`, associated to the specified

/// `appKey`, and write log, upon transition to alive state.

678098 · 2024-10-14T23:46:02Z

src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp

+    int idx          = 1;
+    int numConsumers = 0;
+
+    QueueEngineUtil_AppState::Consumers& consumers = app->consumers();


Suggested change

QueueEngineUtil_AppState::Consumers& consumers = app->consumers();

const QueueEngineUtil_AppState::Consumers& consumers = app->consumers();

678098 · 2024-10-14T23:58:15Z

src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp

+            out << k_EXPR_NUM_LIMIT << " of "
+                << " consumer subscription expressions: ";


Suggested change

out << k_EXPR_NUM_LIMIT << " of "

<< " consumer subscription expressions: ";

out << k_EXPR_NUM_LIMIT << " of "

<< "consumer subscription expressions: ";

Double space here, also, from the log itself it's not clear that not all of the existing expressions were printed due to limit

Added First word in the beginning for clarity, e.g. First 50 of consumer subscription expressions:

678098 · 2024-10-14T23:59:10Z

src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp

+            app->putAsideList().first());
+        if (rc == mqbi::StorageResult::e_SUCCESS) {
+            // Log timestamp
+            out << "Oldest message in a 'Put aside' list:\n";


Suggested change

out << "Oldest message in a 'Put aside' list:\n";

out << "Oldest message in the 'Put aside' list:\n";

Since we are logging info about concrete queue

678098 · 2024-10-15T00:03:13Z

src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp

+                BALL_LOG_WARN << "Failed to streamIn MessageProperties, rc = "
+                              << rc;


Suggested change

BALL_LOG_WARN << "Failed to streamIn MessageProperties, rc = "

<< rc;

BALL_LOG_WARN << "Failed to streamIn MessageProperties, rc = "

<< rc;

out << "Message Properties: Failed to acquire [rc: " << rc << "]\n";

Do we want to print this in the alarm record itself?

678098 · 2024-10-15T00:05:29Z

src/groups/mqb/mqbblp/mqbblp_rootqueueengine.cpp

+            BALL_LOG_WARN << "Failed to get storage iterator for GUID: "
+                          << app->putAsideList().first() << ", rc = " << rc;


Suggested change

BALL_LOG_WARN << "Failed to get storage iterator for GUID: "

<< app->putAsideList().first() << ", rc = " << rc;

BALL_LOG_WARN << "Failed to get storage iterator for GUID: "

<< app->putAsideList().first() << ", rc = " << rc;

out << "'Put aside' list: Failed to acquire [rc: " << rc << "]\n";

Signed-off-by: Aleksandr Ivanov <aivanov71@bloomberg.net>

alexander-e1off · 2024-10-15T07:51:47Z

@678098 thank you, applied your suggestions.

Signed-off-by: Aleksandr Ivanov <aivanov71@bloomberg.net>

678098

LGTM!

alexander-e1off and others added 27 commits March 28, 2024 18:28

Fix macro redefinition warnings, add bmqstoragetool.td target

f02419e

Signed-off-by: Aleksandr Ivanov <aivanov71@bloomberg.net>

Merge branch 'bloomberg:main' into main

122344f

Merge branch 'bloomberg:main' into main

9e23230

Fix order of objects creation in unit test

9117ac7

Signed-off-by: Aleksandr Ivanov <aivanov71@bloomberg.net>

Merge branch 'bloomberg:main' into main

87cdf0b

Merge branch 'bloomberg:main' into main

8e88dc2

Merge branch 'bloomberg:main' into main

6dfd1fa

Merge branch 'bloomberg:main' into main

4ba1056

Merge branch 'bloomberg:main' into main

dcae5bf

Merge branch 'bloomberg:main' into main

7482e16

Merge branch 'bloomberg:main' into main

81a0854

Merge branch 'bloomberg:main' into main

2e29ae8

Merge branch 'bloomberg:main' into main

924c207

Merge branch 'bloomberg:main' into main

f279efd

Merge branch 'bloomberg:main' into main

8142686

Merge branch 'bloomberg:main' into main

2b5eaad

Merge branch 'bloomberg:main' into main

917e8a1

Merge branch 'bloomberg:main' into main

b1f9170

Merge branch 'bloomberg:main' into main

9bf33e6

Merge branch 'bloomberg:main' into main

66e3001

Enhance queue alarm log with subscriptions info

3c6651f

Signed-off-by: Aleksandr Ivanov <aivanov71@bloomberg.net>

Debug message properties

69da6c1

Signed-off-by: Aleksandr Ivanov <aivanov71@bloomberg.net>

Add logging of oldest message in put aside queue and its properties

493b459

Signed-off-by: Aleksandr Ivanov <aivanov71@bloomberg.net>

Fix mqbblp_queueconsumptionmonitor.t

b972874

Signed-off-by: Aleksandr Ivanov <aivanov71@bloomberg.net>

Rename alarm label

763563f

Signed-off-by: Aleksandr Ivanov <aivanov71@bloomberg.net>

Remove CI debug

d092e76

Signed-off-by: Aleksandr Ivanov <aivanov71@bloomberg.net>

Cleanup

d2a5164

Signed-off-by: Aleksandr Ivanov <aivanov71@bloomberg.net>

dorjesinpo requested changes Sep 13, 2024

View reviewed changes

dorjesinpo assigned alexander-e1off Sep 18, 2024

alexander-e1off and others added 7 commits September 23, 2024 06:21

Get rid of headCb

d4cf81d

Signed-off-by: Aleksandr Ivanov <aivanov71@bloomberg.net>

Fix UT

1982cc2

Signed-off-by: Aleksandr Ivanov <aivanov71@bloomberg.net>

Cleanup

76744df

Signed-off-by: Aleksandr Ivanov <aivanov71@bloomberg.net>

Fix Solaris build

a95ed92

Signed-off-by: Aleksandr Ivanov <aivanov71@bloomberg.net>

Merge branch 'bloomberg:main' into enhance-alarm-log

265b77c

Add test_alarms_subscription_mismatch

b29a25c

Signed-off-by: Aleksandr Ivanov <aivanov71@bloomberg.net>

Cleanup

4e11d2d

Signed-off-by: Aleksandr Ivanov <aivanov71@bloomberg.net>

alexander-e1off marked this pull request as ready for review September 24, 2024 14:49

alexander-e1off requested a review from a team as a code owner September 24, 2024 14:49

Merge branch 'bloomberg:main' into enhance-alarm-log

6f7238f

dorjesinpo requested changes Sep 29, 2024

View reviewed changes

alexander-e1off and others added 6 commits September 30, 2024 17:45

Fix review comments

1616eb0

Signed-off-by: Aleksandr Ivanov <aivanov71@bloomberg.net>

Refactor mqbblp_queueconsumptionmonitor.t

85a3eef

Signed-off-by: Aleksandr Ivanov <aivanov71@bloomberg.net>

Print appId in queue uri

88cd3df

Signed-off-by: Aleksandr Ivanov <aivanov71@bloomberg.net>

Merge branch 'bloomberg:main' into main

c6c332e

Merge from main, fix merge conflicts

f853ebf

Signed-off-by: Aleksandr Ivanov <aivanov71@bloomberg.net>

Fix code formatting

24d2027

Signed-off-by: Aleksandr Ivanov <aivanov71@bloomberg.net>

alexander-e1off commented Oct 14, 2024

View reviewed changes

dorjesinpo previously approved these changes Oct 14, 2024

View reviewed changes

678098 requested changes Oct 15, 2024

View reviewed changes

Fix review comments

e1b55b8

Signed-off-by: Aleksandr Ivanov <aivanov71@bloomberg.net>

alexander-e1off dismissed dorjesinpo’s stale review via e1b55b8 October 15, 2024 07:50

Merge branch 'main' into enhance-alarm-log

047955c

Fix failed IT

b4e100f

Signed-off-by: Aleksandr Ivanov <aivanov71@bloomberg.net>

678098 approved these changes Oct 15, 2024

View reviewed changes

alexander-e1off merged commit 71b4dab into bloomberg:main Oct 15, 2024
30 checks passed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Feat[MQB]: Enhance queue consumption monitor alarm log with additional details #420

Feat[MQB]: Enhance queue consumption monitor alarm log with additional details #420

alexander-e1off commented Sep 13, 2024 •

edited

Loading

dorjesinpo left a comment

alexander-e1off commented Sep 16, 2024

alexander-e1off commented Sep 16, 2024 •

edited

Loading

dorjesinpo commented Sep 18, 2024

dorjesinpo left a comment

dorjesinpo Sep 29, 2024

alexander-e1off Oct 14, 2024

dorjesinpo Sep 29, 2024

alexander-e1off Oct 14, 2024

dorjesinpo Sep 29, 2024

dorjesinpo Sep 29, 2024

alexander-e1off Oct 14, 2024

alexander-e1off Oct 14, 2024

dorjesinpo left a comment

678098 left a comment

678098 Oct 14, 2024 •

edited

Loading

678098 Oct 14, 2024 •

edited

Loading

678098 Oct 14, 2024

678098 Oct 14, 2024

678098 Oct 14, 2024

678098 Oct 14, 2024

678098 Oct 14, 2024

alexander-e1off Oct 15, 2024

678098 Oct 14, 2024

678098 Oct 15, 2024

678098 Oct 15, 2024

alexander-e1off commented Oct 15, 2024

678098 left a comment

		/// Update the specified 'subStreamInfo', associated to the specified
		/// 'appKey', and write log, upon transition to alive state.

	QueueEngineUtil_AppState::Consumers& consumers = app->consumers();
	const QueueEngineUtil_AppState::Consumers& consumers = app->consumers();

		out << k_EXPR_NUM_LIMIT << " of "
		<< " consumer subscription expressions: ";

	out << "Oldest message in a 'Put aside' list:\n";
	out << "Oldest message in the 'Put aside' list:\n";

		BALL_LOG_WARN << "Failed to streamIn MessageProperties, rc = "
		<< rc;

		BALL_LOG_WARN << "Failed to get storage iterator for GUID: "
		<< app->putAsideList().first() << ", rc = " << rc;

Feat[MQB]: Enhance queue consumption monitor alarm log with additional details #420

Feat[MQB]: Enhance queue consumption monitor alarm log with additional details #420

Conversation

alexander-e1off commented Sep 13, 2024 • edited Loading

dorjesinpo left a comment

Choose a reason for hiding this comment

alexander-e1off commented Sep 16, 2024

alexander-e1off commented Sep 16, 2024 • edited Loading

dorjesinpo commented Sep 18, 2024

dorjesinpo left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dorjesinpo left a comment

Choose a reason for hiding this comment

678098 left a comment

Choose a reason for hiding this comment

678098 Oct 14, 2024 • edited Loading

Choose a reason for hiding this comment

678098 Oct 14, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

alexander-e1off commented Oct 15, 2024

678098 left a comment

Choose a reason for hiding this comment

alexander-e1off commented Sep 13, 2024 •

edited

Loading

alexander-e1off commented Sep 16, 2024 •

edited

Loading

678098 Oct 14, 2024 •

edited

Loading

678098 Oct 14, 2024 •

edited

Loading