Splunk Search
×

Join the Conversation

Without signing in, you're just watching from the sidelines. Sign in or Register to connect, share, and be part of the Splunk Community.
cancel
Turn on suggestions
Auto-suggest helps you quickly narrow down your search results by suggesting possible matches as you type.
Showing results for 
Show  only  | Search instead for 
Did you mean: 
Ask a Question

HOWTO monitor previous 2 log lines from a specific log line and calculate time difference?

wm
Loves-to-Learn Everything
‎08-14-2024 07:44 PM

This is my current search query

index=abc sourcetype = example_sourcetype
| transaction startswith="Saved messages to DB" endswith="Done bulk saving messages" keepevicted=t
| eval no_msg_wait_time = mvcount(noMessageHandleCounter) * 1000
| fillnull no_msg_wait_time
| rename duration as processing_time
| eval _raw = mvindex(split(_raw, "
"), -1)
| rex "Done Bulk saving .+ used (?<db_bulk_write_time>\w+)"
| eval processing_time = processing_time * 1000
| eval mq_read_time = processing_time - db_bulk_write_time - no_msg_wait_time
| where db_bulk_write_time > 0
| rename processing_time as "processing_time(ms)", db_bulk_write_time as "db_bulk_write_time(ms)", no_msg_wait_time as "no_msg_wait_time(ms)", mq_read_time as "mq_read_time(ms)"
| table _time, processing_time(ms), db_bulk_write_time(ms), no_msg_wait_time(ms), mq_read_time(ms), Count, _raw



So now for processing_time(ms) column the calculation instead is starting from the 2 previous occurences of All Read threads finished flush the messages to Done bulk saving messages

So in the example below:
2024-08-12 10:02:20,542 will have a processing_time from 10:02:19,417 to 10:02:20,542.

2024-08-12 10:02:19,417 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0

2024-08-12 10:02:20,526 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 1
 Count=1
2024-08-12 10:02:20,542 [39] INFO DistributorCommon.DBHandlerBase [(null)] - Done Bulk saving messages, Count=1, used 6 ms

How can I also create a time series graph on same graph where x axis is time and then y axis is a bar chart of count column + line chart of new processing_time(ms)

Raw log data looks something like:

| makeresults
| eval data = split("2024-08-07 21:13:07,710 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:07,710 [39] INFO DistributorCommon.WMQClient [(null)] - No message to handle (noMessageHandleCounter=4), retry in 1000 ms
2024-08-07 21:13:08,742 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:08,742 [39] INFO DistributorCommon.WMQClient [(null)] - No message to handle (noMessageHandleCounter=5), retry in 1000 ms
2024-08-07 21:13:09,757 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:09,757 [39] INFO DistributorCommon.WMQClient [(null)] - No message to handle (noMessageHandleCounter=6), retry in 1000 ms
2024-08-07 21:13:10,773 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:10,773 [39] INFO DistributorCommon.WMQClient [(null)] - No message to handle (noMessageHandleCounter=7), retry in 1000 ms
2024-08-07 21:13:11,007 [15] INFO DistributorCommon.WMQClient [(null)] - Message Read from Queue, Message Length:4504
2024-08-07 21:13:11,132 [15] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=1), retry in 10 ms.
2024-08-07 21:13:11,257 [15] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=2), retry in 10 ms.
2024-08-07 21:13:11,382 [15] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=3), retry in 10 ms.
2024-08-07 21:13:11,507 [15] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=4), retry in 10 ms.
2024-08-07 21:13:11,632 [15] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=5), retry in 10 ms.
2024-08-07 21:13:11,757 [15] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=6), retry in 10 ms.
2024-08-07 21:13:11,882 [15] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=7), retry in 10 ms.
2024-08-07 21:13:11,882 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 1
2024-08-07 21:13:11,882 [39] INFO DistributorCommon.WMQClient [(null)] - Processing messages, Count=1
2024-08-07 21:13:11,882 [39] INFO DistributorCommon.WMQClient [(null)] - Done Processing messages, Count=1, IsBufferedEvent=True
2024-08-07 21:13:11,882 [39] INFO DistributorCommon.DBHandlerBase [(null)] - Bulk saving messages, Count=1
2024-08-07 21:13:12,007 [39] INFO DistributorCommon.DBHandlerBase [(null)] - Done Bulk saving messages, Count=1, used 113 ms
2024-08-07 21:13:12,007 [15] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=8), retry in 10 ms.
2024-08-07 21:13:12,054 [39] INFO DistributorCommon.WMQClient [(null)] - Saved messages to DB, Q Manager to Commit (Remove messages from Queue)
2024-08-07 21:13:12,132 [15] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=9), retry in 10 ms.
2024-08-07 21:13:12,179 [39] INFO DistributorCommon.WMQClient [(null)] - Clear Write Buffer
2024-08-07 21:13:12,257 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:12,398 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:12,528 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:12,778 [33] INFO DistributorCommon.WMQClient [(null)] - Message Read from Queue, Message Length:4668
2024-08-07 21:13:12,809 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 1
2024-08-07 21:13:12,809 [39] INFO DistributorCommon.WMQClient [(null)] - Processing messages, Count=1
2024-08-07 21:13:12,809 [39] INFO DistributorCommon.WMQClient [(null)] - Done Processing messages, Count=1, IsBufferedEvent=True
2024-08-07 21:13:12,809 [39] INFO DistributorCommon.DBHandlerBase [(null)] - Bulk saving messages, Count=1
2024-08-07 21:13:12,825 [39] INFO DistributorCommon.DBHandlerBase [(null)] - Done Bulk saving messages, Count=1, used 24 ms
2024-08-07 21:13:12,841 [39] INFO DistributorCommon.WMQClient [(null)] - Saved messages to DB, Q Manager to Commit (Remove messages from Queue)
2024-08-07 21:13:12,934 [33] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=1), retry in 10 ms.
2024-08-07 21:13:12,966 [39] INFO DistributorCommon.WMQClient [(null)] - Clear Write Buffer
2024-08-07 21:13:13,059 [33] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=2), retry in 10 ms.
2024-08-07 21:13:13,059 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:13,184 [33] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=3), retry in 10 ms.
2024-08-07 21:13:13,200 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:13,325 [33] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=4), retry in 10 ms.
2024-08-07 21:13:13,341 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:13,466 [33] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=5), retry in 10 ms.
2024-08-07 21:13:13,466 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:13,466 [39] INFO DistributorCommon.WMQClient [(null)] - No message to handle (noMessageHandleCounter=4), retry in 1000 ms
2024-08-07 21:13:13,591 [33] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=6), retry in 10 ms.
2024-08-07 21:13:13,716 [33] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=7), retry in 10 ms.
2024-08-07 21:13:13,841 [33] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=8), retry in 10 ms.
2024-08-07 21:13:13,966 [33] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=9), retry in 10 ms.
2024-08-07 21:13:14,481 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:14,481 [39] INFO DistributorCommon.WMQClient [(null)] - No message to handle (noMessageHandleCounter=5), retry in 1000 ms
2024-08-07 21:13:15,497 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:15,497 [39] INFO DistributorCommon.WMQClient [(null)] - No message to handle (noMessageHandleCounter=6), retry in 1000 ms
2024-08-07 21:13:15,731 [20] INFO DistributorCommon.WMQClient [(null)] - Message Read from Queue, Message Length:7648
2024-08-07 21:13:15,856 [20] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=1), retry in 10 ms.
2024-08-07 21:13:15,981 [20] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=2), retry in 10 ms.
2024-08-07 21:13:16,106 [20] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=3), retry in 10 ms.
2024-08-07 21:13:16,231 [20] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=4), retry in 10 ms.
2024-08-07 21:13:16,356 [20] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=5), retry in 10 ms.
2024-08-07 21:13:16,481 [20] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=6), retry in 10 ms.
2024-08-07 21:13:16,606 [20] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=7), retry in 10 ms.
2024-08-07 21:13:16,606 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 1
2024-08-07 21:13:16,606 [39] INFO DistributorCommon.WMQClient [(null)] - Processing messages, Count=1
2024-08-07 21:13:16,606 [39] INFO DistributorCommon.WMQClient [(null)] - Done Processing messages, Count=1, IsBufferedEvent=True
2024-08-07 21:13:16,606 [39] INFO DistributorCommon.DBHandlerBase [(null)] - Bulk saving messages, Count=1
2024-08-07 21:13:16,622 [39] INFO DistributorCommon.DBHandlerBase [(null)] - Done Bulk saving messages, Count=1, used 11 ms
2024-08-07 21:13:16,637 [39] INFO DistributorCommon.WMQClient [(null)] - Saved messages to DB, Q Manager to Commit (Remove messages from Queue)
2024-08-07 21:13:16,731 [20] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=8), retry in 10 ms.
2024-08-07 21:13:16,762 [39] INFO DistributorCommon.WMQClient [(null)] - Clear Write Buffer
2024-08-07 21:13:16,856 [20] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=9), retry in 10 ms.
2024-08-07 21:13:16,856 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:16,997 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:17,137 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:17,278 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:17,278 [39] INFO DistributorCommon.WMQClient [(null)] - No message to handle (noMessageHandleCounter=4), retry in 1000 ms
2024-08-07 21:13:18,294 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:18,294 [39] INFO DistributorCommon.WMQClient [(null)] - No message to handle (noMessageHandleCounter=5), retry in 1000 ms
2024-08-07 21:13:19,309 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:19,309 [39] INFO DistributorCommon.WMQClient [(null)] - No message to handle (noMessageHandleCounter=6), retry in 1000 ms
2024-08-07 21:13:19,544 [28] INFO DistributorCommon.WMQClient [(null)] - Message Read from Queue, Message Length:13568
2024-08-07 21:13:19,669 [28] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=1), retry in 10 ms.
2024-08-07 21:13:19,794 [28] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=2), retry in 10 ms.
2024-08-07 21:13:19,919 [28] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=3), retry in 10 ms.
2024-08-07 21:13:20,044 [28] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=4), retry in 10 ms.
2024-08-07 21:13:20,169 [28] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=5), retry in 10 ms.
2024-08-07 21:13:20,294 [28] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=6), retry in 10 ms.
2024-08-07 21:13:20,419 [28] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=7), retry in 10 ms.
2024-08-07 21:13:20,419 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 1
2024-08-07 21:13:20,419 [39] INFO DistributorCommon.WMQClient [(null)] - Processing messages, Count=1
2024-08-07 21:13:20,419 [39] INFO DistributorCommon.WMQClient [(null)] - Done Processing messages, Count=1, IsBufferedEvent=True
2024-08-07 21:13:20,419 [39] INFO DistributorCommon.DBHandlerBase [(null)] - Bulk saving messages, Count=1
2024-08-07 21:13:20,434 [39] INFO DistributorCommon.DBHandlerBase [(null)] - Done Bulk saving messages, Count=1, used 12 ms"



It looks something like this now

_timeprocessing_timeCountdb_bulk_write_timeno_msg_wait_time_raw
2024-08-07 21:13:16.6373.79711230002024-08-07 21:13:20,434 [39] INFO DistributorCommon.DBHandlerBase [(null)] - Done Bulk saving messages, Count=1, used 12 ms
2024-08-07 21:13:12.8413.78111130002024-08-07 21:13:16,622 [39] INFO DistributorCommon.DBHandlerBase [(null)] - Done Bulk saving messages, Count=1, used 11 ms
2024-08-07 21:13:12.0540.77112402024-08-07 21:13:12,825 [39] INFO DistributorCommon.DBHandlerBase [(null)] - Done Bulk saving messages, Count=1, used 24 ms
2024-08-07 21:13:07.7104.297111340002024-08-07 21:13:12,007 [39] INFO DistributorCommon.DBHandlerBase [(null)] - Done Bulk saving messages, Count=1, used 113 ms
Tags (1)
0 Karma
Reply

yuanliu
SplunkTrust
SplunkTrust
‎08-14-2024 10:42 PM

(First, thank you for providing data emulation.)  Do you mean something like this?

chart-overlay.png

This feature is called "Chart Overlay" in Splunk search visualization.  You open "Visualization", select "Bar chart" as base visualization, then, in "Format", select "Chart Overlay", as in this illustration:

chart-overlay-nutsbolts.png

For illustration purposes, I also selected "View as Axis" "On" because the two measures are too different numerically.

But back to your search.

How can I also create a time series graph on same graph where x axis is time and then y axis is a bar chart of count column + line chart of new processing_time(ms)

You are doing lots of calculations that do not contribute to this end goal.  If you really want to extract potentially useful information, I would suggest the following

| rex "\S+ \S+\s\[(?<somenumber>\d+)\] (?<log_level>\w+) (?<class>\S+) \[(?<someoutput>[^\]]+)\] - (?<message>.+)"
| rex field=message "^(?<action>[^\(,]+)"
| rex field=message ", used (?<db_bulk_write_time>\d+) (?<time_unit>\w+)"

But the simplest search would be

index=abc sourcetype = example_sourcetype
| rex field=message ", used (?<db_bulk_write_time>\d+) (?<time_unit>\w+)"
| transaction startswith="Saved messages to DB" endswith="Done bulk saving messages" keepevicted=t
| where db_bulk_write_time > 0
| eval duration = duration * 1000
| timechart span=500ms max(Count) as Count sum(duration) as "processing_time(ms)"

Note I use span=500ms just to make some useful graphs.  You need to adjust to your needs. (And decide whether sum is the correct stats function in your use case.)

Here is a fuller emulation with more unused extractions.

| makeresults
| eval data = split("2024-08-07 21:13:07,710 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:07,710 [39] INFO DistributorCommon.WMQClient [(null)] - No message to handle (noMessageHandleCounter=4), retry in 1000 ms
2024-08-07 21:13:08,742 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:08,742 [39] INFO DistributorCommon.WMQClient [(null)] - No message to handle (noMessageHandleCounter=5), retry in 1000 ms
2024-08-07 21:13:09,757 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:09,757 [39] INFO DistributorCommon.WMQClient [(null)] - No message to handle (noMessageHandleCounter=6), retry in 1000 ms
2024-08-07 21:13:10,773 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:10,773 [39] INFO DistributorCommon.WMQClient [(null)] - No message to handle (noMessageHandleCounter=7), retry in 1000 ms
2024-08-07 21:13:11,007 [15] INFO DistributorCommon.WMQClient [(null)] - Message Read from Queue, Message Length:4504
2024-08-07 21:13:11,132 [15] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=1), retry in 10 ms.
2024-08-07 21:13:11,257 [15] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=2), retry in 10 ms.
2024-08-07 21:13:11,382 [15] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=3), retry in 10 ms.
2024-08-07 21:13:11,507 [15] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=4), retry in 10 ms.
2024-08-07 21:13:11,632 [15] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=5), retry in 10 ms.
2024-08-07 21:13:11,757 [15] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=6), retry in 10 ms.
2024-08-07 21:13:11,882 [15] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=7), retry in 10 ms.
2024-08-07 21:13:11,882 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 1
2024-08-07 21:13:11,882 [39] INFO DistributorCommon.WMQClient [(null)] - Processing messages, Count=1
2024-08-07 21:13:11,882 [39] INFO DistributorCommon.WMQClient [(null)] - Done Processing messages, Count=1, IsBufferedEvent=True
2024-08-07 21:13:11,882 [39] INFO DistributorCommon.DBHandlerBase [(null)] - Bulk saving messages, Count=1
2024-08-07 21:13:12,007 [39] INFO DistributorCommon.DBHandlerBase [(null)] - Done Bulk saving messages, Count=1, used 113 ms
2024-08-07 21:13:12,007 [15] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=8), retry in 10 ms.
2024-08-07 21:13:12,054 [39] INFO DistributorCommon.WMQClient [(null)] - Saved messages to DB, Q Manager to Commit (Remove messages from Queue)
2024-08-07 21:13:12,132 [15] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=9), retry in 10 ms.
2024-08-07 21:13:12,179 [39] INFO DistributorCommon.WMQClient [(null)] - Clear Write Buffer
2024-08-07 21:13:12,257 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:12,398 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:12,528 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:12,778 [33] INFO DistributorCommon.WMQClient [(null)] - Message Read from Queue, Message Length:4668
2024-08-07 21:13:12,809 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 1
2024-08-07 21:13:12,809 [39] INFO DistributorCommon.WMQClient [(null)] - Processing messages, Count=1
2024-08-07 21:13:12,809 [39] INFO DistributorCommon.WMQClient [(null)] - Done Processing messages, Count=1, IsBufferedEvent=True
2024-08-07 21:13:12,809 [39] INFO DistributorCommon.DBHandlerBase [(null)] - Bulk saving messages, Count=1
2024-08-07 21:13:12,825 [39] INFO DistributorCommon.DBHandlerBase [(null)] - Done Bulk saving messages, Count=1, used 24 ms
2024-08-07 21:13:12,841 [39] INFO DistributorCommon.WMQClient [(null)] - Saved messages to DB, Q Manager to Commit (Remove messages from Queue)
2024-08-07 21:13:12,934 [33] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=1), retry in 10 ms.
2024-08-07 21:13:12,966 [39] INFO DistributorCommon.WMQClient [(null)] - Clear Write Buffer
2024-08-07 21:13:13,059 [33] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=2), retry in 10 ms.
2024-08-07 21:13:13,059 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:13,184 [33] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=3), retry in 10 ms.
2024-08-07 21:13:13,200 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:13,325 [33] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=4), retry in 10 ms.
2024-08-07 21:13:13,341 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:13,466 [33] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=5), retry in 10 ms.
2024-08-07 21:13:13,466 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:13,466 [39] INFO DistributorCommon.WMQClient [(null)] - No message to handle (noMessageHandleCounter=4), retry in 1000 ms
2024-08-07 21:13:13,591 [33] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=6), retry in 10 ms.
2024-08-07 21:13:13,716 [33] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=7), retry in 10 ms.
2024-08-07 21:13:13,841 [33] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=8), retry in 10 ms.
2024-08-07 21:13:13,966 [33] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=9), retry in 10 ms.
2024-08-07 21:13:14,481 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:14,481 [39] INFO DistributorCommon.WMQClient [(null)] - No message to handle (noMessageHandleCounter=5), retry in 1000 ms
2024-08-07 21:13:15,497 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:15,497 [39] INFO DistributorCommon.WMQClient [(null)] - No message to handle (noMessageHandleCounter=6), retry in 1000 ms
2024-08-07 21:13:15,731 [20] INFO DistributorCommon.WMQClient [(null)] - Message Read from Queue, Message Length:7648
2024-08-07 21:13:15,856 [20] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=1), retry in 10 ms.
2024-08-07 21:13:15,981 [20] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=2), retry in 10 ms.
2024-08-07 21:13:16,106 [20] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=3), retry in 10 ms.
2024-08-07 21:13:16,231 [20] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=4), retry in 10 ms.
2024-08-07 21:13:16,356 [20] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=5), retry in 10 ms.
2024-08-07 21:13:16,481 [20] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=6), retry in 10 ms.
2024-08-07 21:13:16,606 [20] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=7), retry in 10 ms.
2024-08-07 21:13:16,606 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 1
2024-08-07 21:13:16,606 [39] INFO DistributorCommon.WMQClient [(null)] - Processing messages, Count=1
2024-08-07 21:13:16,606 [39] INFO DistributorCommon.WMQClient [(null)] - Done Processing messages, Count=1, IsBufferedEvent=True
2024-08-07 21:13:16,606 [39] INFO DistributorCommon.DBHandlerBase [(null)] - Bulk saving messages, Count=1
2024-08-07 21:13:16,622 [39] INFO DistributorCommon.DBHandlerBase [(null)] - Done Bulk saving messages, Count=1, used 11 ms
2024-08-07 21:13:16,637 [39] INFO DistributorCommon.WMQClient [(null)] - Saved messages to DB, Q Manager to Commit (Remove messages from Queue)
2024-08-07 21:13:16,731 [20] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=8), retry in 10 ms.
2024-08-07 21:13:16,762 [39] INFO DistributorCommon.WMQClient [(null)] - Clear Write Buffer
2024-08-07 21:13:16,856 [20] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=9), retry in 10 ms.
2024-08-07 21:13:16,856 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:16,997 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:17,137 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:17,278 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:17,278 [39] INFO DistributorCommon.WMQClient [(null)] - No message to handle (noMessageHandleCounter=4), retry in 1000 ms
2024-08-07 21:13:18,294 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:18,294 [39] INFO DistributorCommon.WMQClient [(null)] - No message to handle (noMessageHandleCounter=5), retry in 1000 ms
2024-08-07 21:13:19,309 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:19,309 [39] INFO DistributorCommon.WMQClient [(null)] - No message to handle (noMessageHandleCounter=6), retry in 1000 ms
2024-08-07 21:13:19,544 [28] INFO DistributorCommon.WMQClient [(null)] - Message Read from Queue, Message Length:13568
2024-08-07 21:13:19,669 [28] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=1), retry in 10 ms.
2024-08-07 21:13:19,794 [28] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=2), retry in 10 ms.
2024-08-07 21:13:19,919 [28] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=3), retry in 10 ms.
2024-08-07 21:13:20,044 [28] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=4), retry in 10 ms.
2024-08-07 21:13:20,169 [28] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=5), retry in 10 ms.
2024-08-07 21:13:20,294 [28] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=6), retry in 10 ms.
2024-08-07 21:13:20,419 [28] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=7), retry in 10 ms.
2024-08-07 21:13:20,419 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 1
2024-08-07 21:13:20,419 [39] INFO DistributorCommon.WMQClient [(null)] - Processing messages, Count=1
2024-08-07 21:13:20,419 [39] INFO DistributorCommon.WMQClient [(null)] - Done Processing messages, Count=1, IsBufferedEvent=True
2024-08-07 21:13:20,419 [39] INFO DistributorCommon.DBHandlerBase [(null)] - Bulk saving messages, Count=1
2024-08-07 21:13:20,434 [39] INFO DistributorCommon.DBHandlerBase [(null)] - Done Bulk saving messages, Count=1, used 12 ms", "
")
| mvexpand data
| rename data as _raw
| extract
| rex "(?<_time>\S+ \S+)"
| eval _time = strptime(_time, "%F %T,%3N")
| sort - _time
``` the above emulates
index=abc sourcetype = example_sourcetype
```
| rex "\S+ \S+\s\[(?<somenumber>\d+)\] (?<log_level>\w+) (?<class>\S+) \[(?<someoutput>[^\]]+)\] - (?<message>.+)"
| rex field=message "^(?<action>[^\(,]+)"
| rex field=message ", used (?<db_bulk_write_time>\d+) (?<time_unit>\w+)"
``` finish extractions ```
| transaction startswith="Saved messages to DB" endswith="Done bulk saving messages" keepevicted=t
| where db_bulk_write_time > 0
| eval duration = duration * 1000
| timechart span=500ms max(Count) as Count sum(duration) as "processing_time(ms)"

The screenshots above are produced from this emulation by customizing search period to the interval represented in mock data.

0 Karma
Reply

wm
Loves-to-Learn Everything
‎08-15-2024 01:47 AM

Thanks!! Yes something like x axis time and y axis is count column in bar chart + line chart of processing_time so it looks correct

However I think the processing_time calculation is abit tricky:

How can I calculate the processing_time for the below 21:13:12,825: done bulk saving messages should have a processing_time as per below:

Look at 2nd prev "All read threads finished flush.." which is 21:13:12,528 and take the time difference so is 297ms, but I can't use transaction since there are also many other "all read threads finished in between 2 done bulk saving messages 

2024-08-07 21:13:12,007 [39] INFO DistributorCommon.DBHandlerBase [(null)] - Done Bulk saving messages, Count=1, used 113 ms
2024-08-07 21:13:12,007 [15] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=8), retry in 10 ms.
2024-08-07 21:13:12,054 [39] INFO DistributorCommon.WMQClient [(null)] - Saved messages to DB, Q Manager to Commit (Remove messages from Queue)
2024-08-07 21:13:12,132 [15] INFO DistributorCommon.WMQClient [(null)] - No msg in the queue (NoMessageCounter=9), retry in 10 ms.
2024-08-07 21:13:12,179 [39] INFO DistributorCommon.WMQClient [(null)] - Clear Write Buffer
2024-08-07 21:13:12,257 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:12,398 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:12,528 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 0
2024-08-07 21:13:12,778 [33] INFO DistributorCommon.WMQClient [(null)] - Message Read from Queue, Message Length:4668
2024-08-07 21:13:12,809 [39] INFO DistributorCommon.WMQClient [(null)] - All Read threads finished flush the messages, total messages: 1
2024-08-07 21:13:12,809 [39] INFO DistributorCommon.WMQClient [(null)] - Processing messages, Count=1
2024-08-07 21:13:12,809 [39] INFO DistributorCommon.WMQClient [(null)] - Done Processing messages, Count=1, IsBufferedEvent=True
2024-08-07 21:13:12,809 [39] INFO DistributorCommon.DBHandlerBase [(null)] - Bulk saving messages, Count=1
2024-08-07 21:13:12,825 [39] INFO DistributorCommon.DBHandlerBase [(null)] - Done Bulk saving messages, Count=1, used 24 ms



 

0 Karma
Reply

yuanliu
SplunkTrust
SplunkTrust
‎08-15-2024 10:33 AM

For that, you need to dive very, very deep into semantics of your logs.  Ask your developers how to reconstruct a complete transaction from log entries.  And yes, read transaction, learn about its options.  And practice on mock data.  Semantic problems have no shortcuts.

If you don't want to go semantic, there is delta, and possibly streamstats that can give you lapsed time since the second-to-last event. (Which you put up as subject line for this question.)  However, my reverse engineering based on the sample logs you give gives me very low confidence that counting lines gives any meaningful measure.

0 Karma
Reply
Get Updates on the Splunk Community!

Accelerating Observability as Code with the Splunk AI Assistant

We’ve seen in previous posts what Observability as Code (OaC) is and how it’s now essential for managing ...

Integrating Splunk Search API and Quarto to Create Reproducible Investigation ...

 Splunk is More Than Just the Web Console For Digital Forensics and Incident Response (DFIR) practitioners, ...

Congratulations to the 2025-2026 SplunkTrust!

Hello, Splunk Community! We are beyond thrilled to announce our newest group of SplunkTrust members!  The ...