Feat[MQB]: Add log with session/queue operations time #414
Conversation
Signed-off-by: Aleksandr Ivanov <aivanov71@bloomberg.net>
Signed-off-by: Aleksandr Ivanov <aivanov71@bloomberg.net>
Signed-off-by: Aleksandr Ivanov <aivanov71@bloomberg.net>
Signed-off-by: Aleksandr Ivanov <aivanov71@bloomberg.net>
alexander-e1off
changed the title
Signed-off-by: Aleksandr Ivanov <aivanov71@bloomberg.net>
![bmq-oss-ci[bot]](https://avatars.githubusercontent.com/u/1416818?s=60&v=4){kind=small}
678098
changed the title
| ? streamParamsCtrlMsg.choice().configureQueueStream().qId() | ||
| : streamParamsCtrlMsg.choice().configureStream().qId(); | ||
|
|
||
| mwcu::MemOutStream logStream(&localAlloc); |
There was a problem hiding this comment.
It might be beneficial to convert mwcu::MemOutStream to a field for this class, to avoid construction/deconstruction for any queue operation. It might also reduce the number of allocations
There was a problem hiding this comment.
Added class member d_logOpStream.
| { | ||
| if (d_beginTimestamp) { | ||
| const bsls::Types::Int64 elapsed = | ||
| mwcsys::Time::highResolutionTimer() - d_beginTimestamp; |
There was a problem hiding this comment.
This initialization might be moved to BLOCK INFO, since it's used for logging only
There was a problem hiding this comment.
Moved under BALL_LOG_INFO_BLOCK
|
|
||
| if (begin) { | ||
| const bsls::Types::Int64 elapsed = | ||
| mwcsys::Time::highResolutionTimer() - begin; |
There was a problem hiding this comment.
Might be moved to BLOCK INFO
There was a problem hiding this comment.
Moved under BALL_LOG_INFO_BLOCK
Signed-off-by: Aleksandr Ivanov <aivanov71@bloomberg.net>
| @@ -747,14 +747,32 @@ void ClientSession::onHandleConfiguredDispatched( | |||
| // PRECONDITIONS | |||
| BSLS_ASSERT_SAFE(dispatcher()->inDispatcherThread(this)); | |||
|
|
|||
| bdlma::LocalSequentialAllocator<2048> localAlloc(d_state.d_allocator_p); | |||
There was a problem hiding this comment.
Might be good to move this initialization back down, since there is a code path with early return where this allocator is not constructed (line 771).
| if (isDisconnected()) { | ||
| // The client is disconnected or the channel is down | ||
| logOperationTime(); |
There was a problem hiding this comment.
I think it was good to just pass the stream argument as before, even if we store it as a field now. Now the usage of logOperationTime is a bit obscure, it relies on a hidden dependency on d_logOpStream.
With argument passed, this dependency is shown in the interface.
There was a problem hiding this comment.
I am thinking if it's worth it to rename d_logOpStream to d_currentOpDescription to make it more clear
There was a problem hiding this comment.
Added argument to logOperationTime, renamed to d_currentOpDescription.
| { // Save begin session timestamp | ||
| bslmt::LockGuard<bslmt::Mutex> guard(&d_mutex); // LOCK | ||
| d_timestampMap[channel.get()] = | ||
| mwcsys::Time::highResolutionTimer(); |
There was a problem hiding this comment.
I am concerned about these synchronizations between different threads on channel operations. I believe it's possible to store these timestamps directly in one of the mwcio::Channel implementations, so we don't need a mutex synchronization for them at all.
Let's add TODO for this
There was a problem hiding this comment.
Agree, but for this it's needed to change interface and implementations. So added TODO for now.
Signed-off-by: Aleksandr Ivanov <aivanov71@bloomberg.net>
| if (queueStateIter != d_queueSessionManager.queues().end()) { | ||
| d_currentOpDescription | ||
| << "Configure queue '" | ||
| << queueStateIter->second.d_handle_p->queue()->uri() << "'"; |
There was a problem hiding this comment.
This SEGFAULTs if d_handle_p is 0 (after dropAllQueueHandles)
Augment the logs of broker operations such as start/stop client session as well as open/configure/close queue to contain the human friendly (for easy log read) as well as the nanoseconds time of all operations (in both success and failures).
Log looks like this: