Overcome the 10000 lines limitation of the yarplogger

[S-Dafarra]

The yarplogger is a fundamental tool in the daily use of the robots. It allows to quickly spot errors, and produce useful logs to request help in debugging those errors.

At the moment, the default maximum number of lines for an entry of the logger is 10000. This default value has been set about 7 years ago robotology/yarp@85a3710.

This limit is reached quite easily. It is enough for an error, or a status message, to be printed too often, and pretty soon the log gets saturated, unfortunately (see robotology/icub-main#768 for example).

Unfortunately, we are often in the case in which we need to detect a nasty bug that may occur after hours of robot use. Then, when the problem actually occurs and we want to check what happened, the log saturated minutes earlier and the error message got lost.

We also tried to increase consistently the maximum number of messages, up to 100K. In this case, when we reach a high number of messages, the logger freezes, and the log is once more unusable.

I wonder whether some mechanism could be implemented to avoid missing some messages. For example, a new log entry could be created automatically every time the limit of 10000 is reached.

Any idea?
@pattacini @drdanz @randaz81 @maggia80 @DanielePucci

[pattacini]

I wonder whether some mechanism could be implemented to avoid missing some messages

I'm strongly in favor of implementing anything that may alleviate the pain of losing messages with a platform undergoing heavy usage.

[drdanz]

Do you need the whole log to be available while the robot is running?
I suppose we could store the log in some database, keep the last n lines (10000?) loaded and have some methods to load more.
We could also consider to make the "logger" a service that writes on a database, and a separate GUI, to query the database, and view the data. This could allow us to have more than one GUI at the same time. It might be a little tricky to get the data in realtime, though. Also it could increase the network load.

[S-Dafarra]

I think it is enough to visualize just the last n lines, while storing the entirety of the log. We often just need to know what happened in the past few seconds. Instead, for offline debugging, it is important to have the entire history.

[randaz81]

???
There is no such a limit, it is just a configuration sertting that can changed in the "preferences" menu of the gui. I'm pretty sure in the past i produced a file of 40.000 lines. If the gui freezes in your use case, then it is just a bug that needs to be investigated and fixed...

[S-Dafarra]

Maybe I was barking at the wrong tree. I just noticed that the CPU usage of the logger increases consistently when keeping open a large log.

• Log closed
  
• Log opened
  

I wonder if this could have been a cause of the freeze

[traversaro]

I'll keep the test continuing for the whole day...

[randaz81]

Some more facts after the test:
I was able to save to file a log of several tens of millions of log lines, for a total size of 6Gb. I have not noticed slowdowns on the gui, but I cannot guarantee the quality of implementation for such a big amount of data, and definitely, something can be done to improve memory/cpu usage and to avoid frequent reallocations. I already have some ideas on that -> action point 1

About the freeze you experienced, I currently have the following two opinions.
1- it could be the result of the segmentation fault I fixed in the PR mentioned above. This issue was occurring during the logging. However, if the app is compiled in release instead of debug, it could happen that no message is displayed, just a freeze. So please tell me if with this fix the app freezes again during the logging.
2- if the app freezes NOTt during the logging: i.e. when you press the stop button, the refresh button, or the save to file button. When these actions are performed, large memory reallocation occurs. In my test, pressing the stop button for a log of some millions of entries resulted in a busy wait of more than 10 minutes, and during this time, the gui is not responding at all. At the end of the operation, the GUI becomes functional again. I'm going to improve this soon, by just releasing the thread every xxx operations, so that the user can check a progress bar or something like that -> action point 3
By the way, I noticed the following fun fact: the logger itself cannot log its own status with a yInfo (guess why..) so it uses simple printf() on stderr to notify the user about the progress. However, if you start the logger from yarpmanager, these prints are lost. So, just for debug purposes, for the time being, please launch the logger from the command line. In this way, if something bad happens, then we can read this additional info.

The most severe issue I am currently aware of is that if in the case of heavy traffic, some messages can be eventually lost. This issue is currently addressed by robotology/yarp#2667 but it has some big drawbacks too, so some additional investigation is still required and it cannot be merged right now -> action point 4

I also noticed another minor issue related to the max size of the log that sometimes is reset back to 10000 if you refresh/restart the log session. The bug is easy to fix, I'll open the corresponding PR soon -> action point 5

[S-Dafarra]

Oh, wow, thanks a lot! I was wondering, is there a way to set the max size from configuration parameters, instead of the GUI?
EDIT by randaz81: ok action point 6

EDIT: Regarding the opinions for the freeze, I guess it happened while saving the file. Probably we were not patient enough then.

[pattacini]

Nice writeup!
My only comment is that, when you deem it's the right moment, likely after the action points will be completed, it'd be fundamental to test the logger in a system under heavy usage/traffic, like iCub 3.

[randaz81]

@S-Dafarra The issues # 3, # 5 and # 6 have been fixed by robotology/yarp#2743. As discussed some time ago, I recommend testing it on a dedicated machine, so you can use yarp master branch.

[S-Dafarra]

Thanks a lot!

[randaz81]

A possible solution for issue # 4 (see above) is now given by robotology/yarp#2767 and is under testing.

[S-Dafarra]

Thanks!