Search Unity

  1. Unity 2020.1 has been released.
    Dismiss Notice
  2. Good news ✨ We have more Unite Now videos available for you to watch on-demand! Come check them out and ask our experts any questions!
    Dismiss Notice

Data Logger API: File Generation Rate

Discussion in 'Unity Simulation' started by andor_unity, Jul 3, 2020.

  1. andor_unity

    andor_unity

    Joined:
    Mar 20, 2019
    Posts:
    6
    I'm trying to get the data logger to work correctly for my application, which seems to post log file for EACH simulation tick, which is not expected or desired behavior from my POV.

    Expected:

    A few log files contianing multiple frames per log file. This can be rotated based on size (i.e 10 MB or so) or duration (i.e 200 seconds). I prefer size.

    I tried setting buffer size but that didn't seem to work.

    Actual:
    For 200 frames, I get 200 very small files.
    For example, I put a simple Debug.LogFormat("Logger Path is {0}", logger.GetPath()) and I get Logger Path is is <Path To Logs>/<Logger Name>_<TickNumber>.txt.

    Notes:
    The logger is instantiated as such:

    Code (CSharp):
    1.  
    2. logger  = new Unity.Simulation.Logger("MyLogger");
    3.  
    Without writing to logs and just printing path, I still get tick monotonic update schema.

    Also I looked into the Logger class source code, it doesn't seem based on documentation this is expected behviour. Can you confirm it is and if not, what I am doing wrong?

    Code (CSharp):
    1.    
    2.         /// <summary>
    3.         /// Initializes a new instance of DataCapture logger with given params.
    4.         /// </summary>
    5.         /// <param name="logName">Name of the DataCapture Log file.</param>
    6.         /// <param name="bufferSize">This corresponds to the file size (in KB). Default is set to 8192.</param>
    7.         /// <param name="userPath">Location of the log file. Default is set to Application persistent path.</param>
    8.  
    Thank you for the help.
     
    Last edited: Jul 3, 2020
  2. UnityShaunDon

    UnityShaunDon

    Unity Technologies

    Joined:
    Mar 8, 2019
    Posts:
    3
    Hi! thank you for the question

    I tried this out locally and was not able to reproduce files being created for each Update call. You may find that it is based on size or duration. If that is not the case we will need more information to reproduce the issue.

    As you pointed out in the docstring you can set the bufferSize before the logger will write to a file. Such as
    Code (CSharp):
    1. logger = new Unity.Simulation.Logger("MyLogger", 4096000)
    The second argument to the constructor is in a unit of bytes, contrary to the docstring (we will get that fixed!)

    The logger makes use of a ChunkedStream which will flush after the buffer is full (size) OR a timeout (time), whichever occurs first. The Logger will default to 5 seconds and is not currently exposed in the Logger constructor. If calling the constructor as with the default buffer size I suspect that you are getting a file each 8KB or each 5 seconds. Based on your feedback we will expose the timeout in an upcoming release of the Capture package so that it is configurable.

    Thanks!
     
  3. andor_unity

    andor_unity

    Joined:
    Mar 20, 2019
    Posts:
    6
    @UnityShaunDon thanks for getting back to me!

    A couple things here:

    1. Thanks for informing in bytes. I thought it was killobytes. I've changed that and that helps a little.
    2. Yes. Basically, I'd want to have logs reports for every 10 MB of data that takes at least a few minutes (probably longer to collect)
    3. Code sample below. The logs show incrementing GetPath per tick:
    Writing To /Users/<>/Library/Application Support/<>/UnitySimulationIntegration/8c76c9fc-8737-42dd-b1f9-f21004f9ecc9/Logs/Logs_108.txt
    Writing To /Users/<>/Library/Application Support/<>/UnitySimulationIntegration/8c76c9fc-8737-42dd-b1f9-f21004f9ecc9/Logs/Logs_109.txt

    It seems it flushes and provides numbering based whatever ticks it's at. I'd rather flush to an increment on the FS, such as:
    Logs_1.txt has 10 MB
    Logs_2.txt has 10 MB
    etc...


    Please see below for sample logs with code.

    Code (CSharp):
    1.  
    2.     private Unity.Simulation.Logger agentLogger;
    3.  
    4.     /// <summary>
    5.     ///   On start, instatiate agent Logger.
    6.     /// </summary>
    7.     void Start(){
    8.     agentLogger = new Unity.Simulation.Logger("Logs.txt", 10000000);
    9.         startTime = 0;
    10.     }
    11.  
    12.     /// <summary>
    13.     ///  Flush logs before quitting the aplication
    14.     /// </summary>
    15.     void OnApplicationQuit(){
    16.         agentLogger.Flushall();
    17.     }
    18.  
    19.   /// <summary>
    20.     ///   A simple class to print time
    21.     /// </summary>
    22.     [System.Serializable]
    23.     public class MyTestClass
    24.     {
    25.         public float time;
    26.  
    27.         public MyTestClass(){
    28.             time = Time.time;
    29.         }
    30.    
    31.         public override string ToString()
    32.         {
    33.             return time.ToString();
    34.         }
    35.     }
    36.  
    37.     /// <summary>
    38.     ///   On each update, write the time
    39.     /// </summary>
    40.     public void Update(){
    41.         agentLogger.Log(new MyTestClass());    
    42.         Debug.LogFormat("Writing To {0}", agentLogger.GetPath());
    43.     }
    44.  
    Produces (for a short bit, logs attached):
    A couple things here:

    Time duration in this is not alwasy 5 seconds. ex. 565 only has 2.3 seconds. 90 a well.
    417 is about 5 seconds. 0 is empty.

    I'm not implementing forced flush so this should be default mechanics.

    Hopefully this helps. I don't think this is expected behavior?
     
    Last edited: Jul 6, 2020
  4. andor_unity

    andor_unity

    Joined:
    Mar 20, 2019
    Posts:
    6
    Sorry. Logs here:
     

    Attached Files:

  5. andor_unity

    andor_unity

    Joined:
    Mar 20, 2019
    Posts:
    6
    @UnityShaunDon do you have any thoughts on the above or a release timing for the logging flush fix? For our particular use case, which requires collecting raw log data of simulation, this is a critical requirement for usability.

    Again, generlly looking to have logs in this format: (assuming 10 MB limit and NO timeout)

    Log_1.txt 10MB
    Log_2.txt 10MB
    Log_3.txt 10MB
    Log_4.txt 10MB
     
  6. andor_unity

    andor_unity

    Joined:
    Mar 20, 2019
    Posts:
    6
    @UnityShaunDon

    Can you clarify how the files are generated related to the flush mechanics?

    Was looking at this thread and I just want to make sure that the preferred behavior from my end is captured as I know this is in active development.

    It's possible I'm doing something wrong here or may have erred, in which case please clarify, but I don't believe this is current behvior.

    If I may respectibly suggest what I think woudl be an improvement of mechanics to the Logger....

    I'd suggest something like this:

    Params:

    logRotationSize - controls how large a single log file gets. Defaults to -1?
    bufferSize - controls how large the ChunkedStream buffers before it flushes
    logRotationRate - controls how frequent a log file can get rotated (defaults to -1?)
    logPrefix - the prefix name for each log. Even better would be some custom formatting schema.
    directoryPath - the directory to store the logs. Defaults if not set.

    - When logRotation params are set < 0, then that param is unbounded.
    Otherwise:
    - when the filesize > logRotationSize, it makes a new file with incremented id. i.e Prefix_0.txt becomes Prefix_1.txt
    - when buffer fills, it dumps message to file. This does not have a direct impact on file rotation.
    - when time between two logs > logRotationRate, then creates a new log file.

    This gives you I think proper control over log rotation (I think). Idk with most other customers, but for us log rotation and log mechanics are very important, so we need to have really good control of these.

    I'm sure there are others I haven't considered, but just wanted to point out a few thoughts here in case they help. My apologies in advance if they don't futher help the development of the Logger as I was hoping and I'd appreciate clarification on misunderstanding.

    I'd use this as a reference point as well:
    https://linux.die.net/man/8/logrotate#:~:text=logrotate is designed to ease,as a daily cron job.

    It's not the exact same, but there are probably snippets that can be picked up from here.
     
    Last edited: Jul 7, 2020
  7. priyeshwani

    priyeshwani

    Unity Technologies

    Joined:
    Dec 7, 2016
    Posts:
    4
    Hi, @andor_unity Thanks for your input. We will make sure to address this usecase in our next release. We can certainly expose the maxElapsedTime via Logger constructor and add an option to ignore it as well.

    The issue regarding time duration not being 5s all the time, was that while running it in the cloud or running it locally? we will need to investigate that on our end. Will keep you posted with our next release.
     
  8. andor_unity

    andor_unity

    Joined:
    Mar 20, 2019
    Posts:
    6
    @priyeshwani:

    That was running locally. I could do some tests additional tests as well if you'd like. It's possible that it's something environmental on my end. Can you confirm my understanding of the current mechanics are correct?

    I'd also love to see the other suggestions implemented if possible and if they make sense from your end. If they don't, I'd love to understand the rationale why they don't.
     
  9. priyeshwani

    priyeshwani

    Unity Technologies

    Joined:
    Dec 7, 2016
    Posts:
    4
    Okay, so I was trying it locally and the reason you see Flush happening before the end of 5s is because of the difference in simulation time vs walltime. We use Time.unscaledDeltaTime to account for when the data in the buffer needs to be flushed down to the file system. As a test, you can try switching time = Time.time; to time = Time.unscaledTime
     
  10. priyeshwani

    priyeshwani

    Unity Technologies

    Joined:
    Dec 7, 2016
    Posts:
    4
    @andor_unity
    The new capture package 0.0.10-preview.9 has been published with which you should be able to override the maxElapsedSeconds while creating the logger instance. Setting that to -1 will allow you to flush to the file system when the buffer size reaches the specified bufferSize (8192 bytes by default)
     
unityunity