topic HOWTO monitor previous 2 log lines from a specific log line and calculate time difference? in Splunk Search

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

wm — Thu, 15 Aug 2024 02:44:45 GMT

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

_time	processing_time	Count	db_bulk_write_time	no_msg_wait_time	_raw
2024-08-07 21:13:16.637	3.797	1	12	3000	2024-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.841	3.781	1	11	3000	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:12.054	0.771	1	24	0	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:07.710	4.297	1	113	4000	2024-08-07 21:13:12,007 [39] INFO DistributorCommon.DBHandlerBase [(null)] - Done Bulk saving messages, Count=1, used 113 ms

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

yuanliu — Thu, 15 Aug 2024 05:42:26 GMT

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

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:

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.

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

wm — Thu, 15 Aug 2024 08:47:54 GMT

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

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

yuanliu — Thu, 15 Aug 2024 17:33:53 GMT

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.