Venice "dirty cache" in Avuslogs

Robert Leong -

Ref ticket #25997

Search the Avus logs for " queue " to find the dirty cache.  I believe this applies to records only, playout might not apply.

Buffer logs:

The significant number here is the second to the last. This is indicating how full the buffer is. It should only see maybe a handle full of frames tops, but here the queue reaches over 100 (116/117) frames in buffer then dropping starts to occur.

 Line 56868: 2017-01-11  17:14:04.213806  0.000166  9BFFF700  queue  1  3 117  -1  
 Line 56894: 2017-01-11  17:14:04.228766  0.000065  9BFFF700  queue  **  4 116  +1  
 Line 56948: 2017-01-11  17:14:04.247947  0.000157  9BFFF700  queue  2  3 117  -1  
 Line 56985: 2017-01-11  17:14:04.277698  0.000075  9BFFF700  queue  **  4 116  +1  
 Line 57027: 2017-01-11  17:14:04.281003  0.000141  9BFFF700  queue  2  3 117  -1  
 Line 57068: 2017-01-11  17:14:04.323307  0.000064  9BFFF700  queue  **  4 116  +1 

Here is a normal queue, notice that there is only 1 frame in the buffer queue waiting to be written. (second to the last number)

 Line 97818: 2017-01-11  17:14:22.632151  0.000158  9BFFF700  queue  27 29  1  -1  
 Line 97821: 2017-01-11  17:14:22.632244  0.000054  9BFFF700  queue  ** 30  1  +1  
 Line 97896: 2017-01-11  17:14:22.666259  0.000141  9BFFF700  queue  27 29  1  -1  
 Line 97899: 2017-01-11  17:14:22.666354  0.000065  9BFFF700  queue  ** 30  1  +1  
 Line 97974: 2017-01-11  17:14:22.699761  0.000139  9BFFF700  queue  27 29  1  -1  
 Line 97978: 2017-01-11  17:14:22.699846  0.000063  9BFFF700  queue  ** 30  1  +1  

This tells us for that specific duration something is taking place in the system that triggers the drops. 

Ref ticket #24420

Hi Alexis, use this to look for "dirty queue" in the Venice avus logs.

You can do this by grep for "queue " (there is space in at the end) in the Avus logs. Queue messages look like this:

queue  27 29  3  -1

The third column (3, in this case) is the "dirty queue". It shows the number of frames that have been received by Avus, but not yet written to disk. Normally this is near 0, but your log file shows several times where this value rises. A rising value shows that Avus writes the frames slower than realtime. Avus can cover that for a while, but at 07:47 the value was over 100 (!) and drops occured.
 
The avus logs are in: 

/home/venice/.DVS/logwatched/AvusLog1
/home/venice/.DVS/logwatched/AvusLog2
etc...

A quick cd, ll and grep

# cd /home/venice/.DVS/logwatched/AvusLog1
[root@venice-146120060 AvusLog1]# ll
total 452064
-rw-r--r-- 1 venice users 104857611 Jun 17 17:17 AvusLog1_2016-06-17__16-56-53.txt
-rw-r--r-- 1 venice users 104857644 Jun 17 17:38 AvusLog1_2016-06-17__17-17-50.txt
-rw-r--r-- 1 venice users 104857784 Jun 17 17:58 AvusLog1_2016-06-17__17-38-09.txt
-rw-r--r-- 1 venice users  99978786 Jun 21 14:41 AvusLog1_2016-06-17__17-58-31.txt
-rw-r--r-- 1 venice users  47860658 Feb  3 12:01 AvusLog1_2016-Feb-03 11:42:18.792805.txt

# grep "queue " * | more
AvusLog1_2016-06-17__16-56-53.txt:2016-06-17  16:56:52.617066  0.000035  3D7FB700  queue   6  7  0  -1
AvusLog1_2016-06-17__16-56-53.txt:2016-06-17  16:56:52.617261  0.000174  3D7FB700  queue  **  8  0  +1
AvusLog1_2016-06-17__16-56-53.txt:2016-06-17  16:56:52.650397  0.000047  3D7FB700  queue   6  7  0  -1
AvusLog1_2016-06-17__16-56-53.txt:2016-06-17  16:56:52.650598  0.000183  3D7FB700  queue  **  8  0  +1
AvusLog1_2016-06-17__16-56-53.txt:2016-06-17  16:56:52.683553  0.000028  3D7FB700  queue   6  7  0  -1

 

Have more questions? Submit a request

0 Comments

Article is closed for comments.