Game Binary not keeping chat log open.

Discussion in 'Feedback' started by AoiBlue, Aug 9, 2020.

  1. AoiBlue

    AoiBlue Avatar

    Messages:
    363
    Likes Received:
    259
    Trophy Points:
    55
    Gender:
    Male
    Upon examining the game binary's (Linux) running with lsof, I found it is not holding the chat log file open. I can only presume it is opening and closing it with each write. While I know this affects Linux, I suspect it affects Windows as well.

    This introduces several performance issues:
    1. Creation and destruction of file handles with each write and thus creating GC load, and possible memory leaks.
    2. No active file handle, resulting in poor OS file handling performance.
    3. Synchronizing file output on close, even if written in async mode, freezing world thread until the write is completed.

    The last one is the greatest hit resulting in 75-250ms of world freeze on a rotational disk for each chat message logged to disk. Note that this includes each looting message, and each combat hit.

    There are two possible solutions:
    1. Create a pipe to file for handling chat logging.
    2. Use an Asynchronous buffer for chat logging.

    For option number two I recommend using a good 8MB buffer and very low sync frequency. This will reduce log write frequency further improving performance. Option one will rely on the OS, and thus you simply don't have to worry about it.
     
  2. Ravalox

    Ravalox Dev At Large Moderator SOTA Developer

    Messages:
    865
    Likes Received:
    1,913
    Trophy Points:
    105
    Gender:
    Male
    Location:
    Austin, TX
    This is not a bug, but may be good feedback. Moving the thread to feedback.

    As a reminder for all, commentary on existing game content, features or functionlity should be posted in feedback.

    Posts related to content features or functionality that does not exist in game would go in the wishlist.
     
    Anpu likes this.
  3. Elgarion

    Elgarion Community Manager Moderator SOTA Developer

    Messages:
    2,205
    Likes Received:
    5,947
    Trophy Points:
    153
    Gender:
    Male
    I got a response from the team, "While opening and closing a file can take a few ms or a dozen on a platter drive (not 250ms) it is threaded and system cached. Also, these are queued so it doesn't do this once per message." Hopefully this helps clear up your concerns. Many thanks for the suggestion!
     
    Anpu likes this.
  4. Chris

    Chris Tech Lord Moderator SOTA Developer Ambassador

    Messages:
    2,452
    Likes Received:
    27,629
    Trophy Points:
    190
    Gender:
    Male
    This is not a performance problem. We are using a queue system in front of Unity's logger for the file side of things. It happens in a second thread and does not block. I have also tested locally both on 5400RPM platter drive and a PCIe NVME drive that is 1000 times faster and performance even in heavy stress situations was roughly the same. I'm not 100% certain what Unity is doing in their log function once we hand it off but it definitely isn't blocking. I know this is the case for Windows and I believe it is the same for Linux/OSX but haven't verified it.
     
    Anpu and Alley Oop like this.
  5. Echondas

    Echondas Bug Hunter

    Messages:
    2,320
    Likes Received:
    2,942
    Trophy Points:
    165
    Gender:
    Male
    Location:
    NY
    Are there any command line options or something to disable all logging and sound - for troubleshooting/performance testing purposes? I've wanted to try that for a while, but never asked.
     
    that_shawn_guy likes this.
  6. Browncoat Jayson

    Browncoat Jayson Legend of the Hearth

    Messages:
    6,228
    Likes Received:
    13,864
    Trophy Points:
    153
    There is (or at least, was) a command line option to disable the log. I don't know about sound.
    https://sotawiki.net/sota/Commands#Disable_Log
     
    Alley Oop and Echondas like this.
  7. Echondas

    Echondas Bug Hunter

    Messages:
    2,320
    Likes Received:
    2,942
    Trophy Points:
    165
    Gender:
    Male
    Location:
    NY
    I tried it - but it didn't work 100%: I'm still seeing chat log -- the "output_log.txt" stopped tho.
     
  8. Alley Oop

    Alley Oop Bug Hunter Bug Moderator

    Messages:
    9,996
    Likes Received:
    15,622
    Trophy Points:
    153
    that looks right. the wiki should probably be synced with the unity docs:

    https://docs.unity3d.com/Manual/CommandLineArguments.html

    (scroll down to the standalone player section)
     
    Browncoat Jayson and Echondas like this.
  9. Echondas

    Echondas Bug Hunter

    Messages:
    2,320
    Likes Received:
    2,942
    Trophy Points:
    165
    Gender:
    Male
    Location:
    NY
    Awesome - I didn't know the flags were for Unity not SOTA .. which is good, because now I can whine that Unity doesn't have an option to disable audio ..
    That actually boggles my mind a commercially available engine is missing that .. I'm turning into Chris and ranting about Unity .. time to take a break for today :D
     
    Anpu and Alley Oop like this.
  10. Browncoat Jayson

    Browncoat Jayson Legend of the Hearth

    Messages:
    6,228
    Likes Received:
    13,864
    Trophy Points:
    153
    Anpu, Echondas and Alley Oop like this.
  11. AoiBlue

    AoiBlue Avatar

    Messages:
    363
    Likes Received:
    259
    Trophy Points:
    55
    Gender:
    Male
    It's causing massive performance issues which is why it got put in bugs.

    Sorry if I wasn't clear on this.

    As a note, the disable log option disables the debug log, not the chat log.
     
  12. Ravalox

    Ravalox Dev At Large Moderator SOTA Developer

    Messages:
    865
    Likes Received:
    1,913
    Trophy Points:
    105
    Gender:
    Male
    Location:
    Austin, TX
    It's operating as intended per the implementation, so it would not be classified as a bug. In addition, Chris replied to the thread above. Here's a quote of his response for convenience ...

     
  13. AoiBlue

    AoiBlue Avatar

    Messages:
    363
    Likes Received:
    259
    Trophy Points:
    55
    Gender:
    Male
    Are you sure he's referring to the chat log, and not the Unity error log?

    An A/B test marking the directory for chat logs read-only does see massive performance gain with logging blocked by marking the chat-log directory read only. I am talking about a performance gain of 20fps, and a drastic reduction in both hitch time and hitch frequency.
     
  14. that_shawn_guy

    that_shawn_guy Bug Hunter

    Messages:
    1,025
    Likes Received:
    2,680
    Trophy Points:
    125
    Location:
    earth... mostly
    @AoiBlue Great idea for a test!

    @Ravalox even if this is working as intended, at least give us an option to turn off the chat log. It would allow a wider range of players to easily test this and potentially improve performance on lower-end machines.
     
  15. AoiBlue

    AoiBlue Avatar

    Messages:
    363
    Likes Received:
    259
    Trophy Points:
    55
    Gender:
    Male
    Absolutely, and it will give an easier A/B test in case Unity's analytics and profiling tools are giving misleading results to Chris.

    This would also be useful for regular players who don't want gigabytes of chat logs building up on their hard drives. Preferably it should be put in the options for convenience. Ideally you should be able to select what to log as well so we don't bog down our logs with 20 lines of "Aoi TheBlue did 10 dmg to Naughty Brat with Ring of Fire" every second but can still log ACTUAL chat messages.

    It's a shame a certain monopolistic Redmond based company removed Posix pipes from their Operating System a few years back, or it would be easy to just use a pipe to handle logging. This would be much cleaner and faster, as it would let the OS handle the appending, but because of this doing so would involve OS specific code for one OS everyone still uses despite hating due to the bandwagon paradox of market share making monopolies hard to break.
     
    Last edited: Sep 19, 2020
    that_shawn_guy likes this.
  16. AoiBlue

    AoiBlue Avatar

    Messages:
    363
    Likes Received:
    259
    Trophy Points:
    55
    Gender:
    Male
    BTW, While we have the dev's attention. Is chris working looking through the tasks either running on main thread only or locking the main thread and fixing them, as well as his task of reducing memory pressure by moving temporary variables local. Those are the two biggest offenders in any game engine, and they hit Unity VERY hard.

    My big concern is that some of the lot object loading might be being done in World Thread or with synchronous IO, preventing proper threading of it. Ideally it should be threaded across all available processors in the background only coordinating with the main thread through a queue list for each thread and some status variables.