Heavy slowdown at the Water Production zone on Kodiak map

rkfgrkfg Russia Join Date: 2013-09-03 Member: 187744Members, Reinforced - Supporter, Reinforced - Silver, Reinforced - Gold, Reinforced - Diamond, Reinforced - Shadow
edited October 2014 in Technical Support
I recorded two plogs there: first and second. Both seem to be wasting time at FileSystem::OpenFile for some reason. When there are many players at that zone, the game becomes unplayable. It's not a caching issue since it happens every time I get there, not just the first time. There are places where lags don't occur, but they happen at the res point when you look at the marine base entrance.
«1

Comments

  • rkfgrkfg Russia Join Date: 2013-09-03 Member: 187744Members, Reinforced - Supporter, Reinforced - Silver, Reinforced - Gold, Reinforced - Diamond, Reinforced - Shadow
    Any updates on this? I have more plogs + log.txt, lategame becomes a slideshow in that area.
  • LokiLoki Join Date: 2012-07-07 Member: 153973Members, Forum Moderators, NS2 Playtester, Squad Five Blue, Squad Five Silver, Squad Five Gold, NS2 Map Tester, Reinforced - Shadow, WC 2013 - Shadow, Subnautica Playtester, NS2 Community Developer, Pistachionauts
    edited December 2014
    This is the first I am aware of this issue (being the map guy), unfortunately the plogs don't help me.

    For me to track this issue down for you by looking at the level files I will need screen shots with r_stats active, please take them when looking in the direction where its bad etc.
    IF you can recreate this issue on a private server then I would turn cheats on and type r_wireframe, and again take some screen shots, this will allow me to work out what is being rendered etc

    It would also be useful to know your system specs and the graphics settings you use to play the game. In addition to this, is it specific servers that cause this or all ? The more information the better it will help me.

    I will also ask that one of our programmers have a look. However this is not a promise as they are very busy.

    Summon me back with @Loki when you got your info as I often dont check the tech forums :)
  • rkfgrkfg Russia Join Date: 2013-09-03 Member: 187744Members, Reinforced - Supporter, Reinforced - Silver, Reinforced - Gold, Reinforced - Diamond, Reinforced - Shadow
    edited December 2014
    @Loki‌ I've done what you asked, here are the results:
    1) The screenshots. 60+ FPS is ok, 20-25 is bad and laggy as hell, I've captured both situations at the same location, sometimes looking just a bit to the side makes FPS much better. The slowdown is stable (i.e. not random and tied to the position and look direction) if I look back at the same direction as before, it drops just like it did before.
    ab8904b1c1f186331295ea12001519.jpg
    8cdc8c204f93b9c92bf035c5a52c3c.jpg
    b5ec40b637e913dc75874627fe7865.jpg
    ea737aa6b21b4d9b3f55110dde9b4f.jpg
    7e48d2035a58da3e0bb45055a122ee.jpg
    ec41bd6650abc3d6a5ad0138fe71f7.jpg
    9e7206d12fdc0c71cf5cef3c71aa80.jpg
    fecb5e38f8600cccfd6c9db6ee0baf.jpg
    1d9917a43097eb153de3cc826caee7.jpg
    2) My specs are in the signature: Intel Core i7-2600, 32Gb RAM, NVIDIA GeForce 770 GTX driver v340.46, Debian Jessie GNU/Linux amd64, Awesome WM 3.4.15, kernel v3.17
    3) Graphic settings are on the minimum, except textures which are on High and Reflections turned on. Texture handling is on 1.5 Gb. I don't have FPS issues on other maps and at other areas on Kodiak.
    4) This happens on any server I've played. These particular shots were done on a local sandbox server.

    Thanks for your help!
  • rkfgrkfg Russia Join Date: 2013-09-03 Member: 187744Members, Reinforced - Supporter, Reinforced - Silver, Reinforced - Gold, Reinforced - Diamond, Reinforced - Shadow
    I guess @Asraniel‌ and @murray‌ may have some ideas about this issue. It's stable and reproducible 100% of time, should be pretty easy to hunt down. I play NS2 daily so I can response in a matter of hours if more info is required.
  • IronHorseIronHorse Developer, QA Manager, Technical Support & contributor Join Date: 2010-05-08 Member: 71669Members, Super Administrators, Forum Admins, Forum Moderators, NS2 Developer, NS2 Playtester, Squad Five Blue, Subnautica Playtester, Subnautica PT Lead, Pistachionauts
    I bet its related to the Opengl-Not-Being-Really-Fullscreen issue..
  • rkfgrkfg Russia Join Date: 2013-09-03 Member: 187744Members, Reinforced - Supporter, Reinforced - Silver, Reinforced - Gold, Reinforced - Diamond, Reinforced - Shadow
    Errr, then why it's the only one zone out of all maps and zones? And it really eats up a lot of time inside the OpenFile method. It looks to me more like a missing resource or file, there are some error message in the log (see plog.zip above) regarding something like that.
  • LokiLoki Join Date: 2012-07-07 Member: 153973Members, Forum Moderators, NS2 Playtester, Squad Five Blue, Squad Five Silver, Squad Five Gold, NS2 Map Tester, Reinforced - Shadow, WC 2013 - Shadow, Subnautica Playtester, NS2 Community Developer, Pistachionauts
    Well I cant see anything wrong from a map perspective, however I have added in some additional occlusion geo to the central ice pillar in that room, It might not fix your issue at all. It is the only thing I can do in the editor.

    I imagine this can only be fixed with code :/ and I cant do that so unless you can code linux :D (if you can become a pt etc)
  • rkfgrkfg Russia Join Date: 2013-09-03 Member: 187744Members, Reinforced - Supporter, Reinforced - Silver, Reinforced - Gold, Reinforced - Diamond, Reinforced - Shadow
    Thanks for your efforts! Can you upload the changed map somewhere so I could test it?
  • IronHorseIronHorse Developer, QA Manager, Technical Support & contributor Join Date: 2010-05-08 Member: 71669Members, Super Administrators, Forum Admins, Forum Moderators, NS2 Developer, NS2 Playtester, Squad Five Blue, Subnautica Playtester, Subnautica PT Lead, Pistachionauts
    OpenFile should only cause a hitch, though, not a continuous issue causing 50 ms of waiting on render thread..
  • rkfgrkfg Russia Join Date: 2013-09-03 Member: 187744Members, Reinforced - Supporter, Reinforced - Silver, Reinforced - Gold, Reinforced - Diamond, Reinforced - Shadow
    If it does that continuously it can cause many hitches thus slowing the render thread down, no?
  • LokiLoki Join Date: 2012-07-07 Member: 153973Members, Forum Moderators, NS2 Playtester, Squad Five Blue, Squad Five Silver, Squad Five Gold, NS2 Map Tester, Reinforced - Shadow, WC 2013 - Shadow, Subnautica Playtester, NS2 Community Developer, Pistachionauts
    nah sorry its tied in to build 272 :D
  • rkfgrkfg Russia Join Date: 2013-09-03 Member: 187744Members, Reinforced - Supporter, Reinforced - Silver, Reinforced - Gold, Reinforced - Diamond, Reinforced - Shadow
    Hmm, if each map change would require waiting for another build then fixing this issue would take quite a lot of time... :/
  • matsomatso Master of Patches Join Date: 2002-11-05 Member: 7000Members, Forum Moderators, NS2 Developer, Constellation, NS2 Playtester, Squad Five Blue, Squad Five Silver, Squad Five Gold, Reinforced - Shadow, NS2 Community Developer
    edited December 2014
    Hmm.. seems like the rendering thread is opening files, which it is not supposed to do. Use the console command "f_critlog on" to turn on file logging; it will write opened files on the log (and which thread opened them; ignore threads other than "MainThread" - anything starting with "Worker-x" is just the background texture loading running).

    I could not replicate the file opens in that location, but I'm on a Windows x64 system, which may be the difference here... my guess, considering that the same number of files are being opened all the time, is that there are one or more model files that fails to load on linux. Shader incompatibility, most probably... in which case it will be easy to fix once we know the name of the files being loaded.
  • rkfgrkfg Russia Join Date: 2013-09-03 Member: 187744Members, Reinforced - Supporter, Reinforced - Silver, Reinforced - Gold, Reinforced - Diamond, Reinforced - Shadow
    Ok, two things:
    1) the command is probably just f_critlog, if I add anything as a parameter it answers "Critical thread file logging disabled". If I enter it without parameters, it says "Critical thread file logging enabled".
    2) Either way I have nothing about files in the log. I enabled this command after getting to the problematic zone. I've tried p_logall but there's also nothing about files there.

    BTW, there's a big hole in that area, it was passable in the first map release and then was patched. However, I can see through it as a skulk: http://imgur.com/a/n5M0z FPS drops when that hole is near the screen center but it's not directly connected. When it's on the side of view (but still visible) FPS may be nice. I suspect some geometry can't be rendered but why the FPS drop gets away when I see it but not look at it directly?
  • IronHorseIronHorse Developer, QA Manager, Technical Support & contributor Join Date: 2010-05-08 Member: 71669Members, Super Administrators, Forum Admins, Forum Moderators, NS2 Developer, NS2 Playtester, Squad Five Blue, Subnautica Playtester, Subnautica PT Lead, Pistachionauts
    edited December 2014
    Enable the command before starting anything / going to the trouble area. (assuming you are also restarting your PC before doing this test)

    Also could you snag a profiler screenshot in that same location you were getting 50 ms wait times? (the first screen)
    Thanks
  • rkfgrkfg Russia Join Date: 2013-09-03 Member: 187744Members, Reinforced - Supporter, Reinforced - Silver, Reinforced - Gold, Reinforced - Diamond, Reinforced - Shadow
    edited December 2014
    Ok. I've tried with executing the command right after starting the game but nothing appeared in the log about opened files. The profiler screenshots follow:
    1d873886198102c7396411eed0621d.jpg00ba6deb2ef8b890149b42962c0659.jpg
    I did it for both aliens and marines to rule out the possibility that it only happens to aliens. Nope, looks identical.

    On a side note, forum image uploading sucks, it doesn't show thumbnails and inserts images with HTML tags instead of BBCode. I have to convert them with
    sed 's#<img src="\([^"]*\)" />#[img]\1[/img]#g'
    
  • matsomatso Master of Patches Join Date: 2002-11-05 Member: 7000Members, Forum Moderators, NS2 Developer, Constellation, NS2 Playtester, Squad Five Blue, Squad Five Silver, Squad Five Gold, Reinforced - Shadow, NS2 Community Developer
    rkfg wrote: »
    Ok, two things:
    1) the command is probably just f_critlog, if I add anything as a parameter it answers "Critical thread file logging disabled". If I enter it without parameters, it says "Critical thread file logging enabled".
    2) Either way I have nothing about files in the log. I enabled this command after getting to the problematic zone. I've tried p_logall but there's also nothing about files there.

    Mmm... I misremebered how the f_critlog behaves ... simpler to just turn on complete filesystem logging.

    Try "f_log" instead. "f_log" to turn on, "f_log off" to turn off.

  • develdevel Join Date: 2014-09-13 Member: 198444Members
    edited December 2014
    I've got some logs. Tried to post yesterday, but forum was a bit broken.

    Some holiday/workshop files are constantly opening when looking there.
  • rkfgrkfg Russia Join Date: 2013-09-03 Member: 187744Members, Reinforced - Supporter, Reinforced - Silver, Reinforced - Gold, Reinforced - Diamond, Reinforced - Shadow
    Well, this is at the same time embarassing and very interesting. Embarassing, because it's partly because of mods, I haven't bothered to turn them off because they in no way could affect the performance (custom crosshair, Exo font and Shotgun fix for Linux). But they did, though not in the way one could think.

    It's interesting because without mods the slowdown is almost negligible but it's still there, and there's nothing in the f_log at that time. There are, of course, many other file access lines when the map is being loaded and a bit after the game start and the first evolving. It looks like precaching doesn't cache really everything, so a couple of hitches right after the start is explainable. But when I have FPS drop there's nothing in the console and the log file. The OpenFile call in the render thread is still there though. So, why mods make it this heavy? Mu guess is because of the virtual filesystem the game builds in the runtime. It mounts mods directories over each other and hence when it tries to open that mysterious unknown file it has to traverse not only the main data directory but also all the mods ones. I noticed that logic is now put into a zip file so this should be much faster than reading the native FS due to keeping the zip dir structure in the memory completely. Here's the screenshot of the profiler running without any mods:
    b039642686a37d4413e52ad5177040.jpg
    I'm also attaching the log file. I went to the WP Zone with and without mods turning them on and off, so there are several sessions in one file.
  • rkfgrkfg Russia Join Date: 2013-09-03 Member: 187744Members, Reinforced - Supporter, Reinforced - Silver, Reinforced - Gold, Reinforced - Diamond, Reinforced - Shadow
    @devel wow, strace is great! It could be better with timestamps to estimate the frequency of those calls. I definitely should learn how to strace effectively, it's an amazing tool when everything else has failed.
  • rkfgrkfg Russia Join Date: 2013-09-03 Member: 187744Members, Reinforced - Supporter, Reinforced - Silver, Reinforced - Gold, Reinforced - Diamond, Reinforced - Shadow
    edited December 2014
    Well, I've managed to man strace enough to capture some useful data.
    PLvrh2m.gif

    As it shows, the problematic file is (drumroll!) /seasonal/holiday2012/models/xmas_rock_mid_str_128.model.

    Which is missing. I have no idea what that file should do at that place, probably cork that nasty hole. Now the strange part: the file actually exists and looks well BUT strace shows that the filename has a redundant period in the end. And probably that's it. That dot should be removed wherever it's referenced in the map and things should go well after that.

    PS: opening files in the render thread is a bad idea anyway, spare our framerates, please!
  • matsomatso Master of Patches Join Date: 2002-11-05 Member: 7000Members, Forum Moderators, NS2 Developer, Constellation, NS2 Playtester, Squad Five Blue, Squad Five Silver, Squad Five Gold, Reinforced - Shadow, NS2 Community Developer
    The reason it opens it during the game is because it fails to load it; normally all model files used in the game and the map are loaded during the dreaded map load time ("Preaching..." etc).

    But because it fails to load it then, it will then try to load it when it is needed - ie, on every frame when you are looking in the wrong direction. Which is kinda silly, but then, files should not fail to load. And when they do fail to load, they should say so at least once. You would think... :-(
  • SamusDroidSamusDroid Colorado Join Date: 2013-05-13 Member: 185219Members, Forum Moderators, NS2 Developer, NS2 Playtester, Squad Five Gold, Subnautica Playtester, NS2 Community Developer, Pistachionauts
    Can you go around other maps and run that, it would be interesting to see what other maps might have this problem
  • rkfgrkfg Russia Join Date: 2013-09-03 Member: 187744Members, Reinforced - Supporter, Reinforced - Silver, Reinforced - Gold, Reinforced - Diamond, Reinforced - Shadow
    edited December 2014
    @SamusDroid‌ No problem, I'll try it.
    @matso‌ I understand this logic but unfortunately (and I've learned this the hard way being a programmer myself) assuming that something "should not happen" often result in the most cryptic bugs. Because it, well, happens. Probably it should drop a big fat warning to the log that some resource wasn't found (it's a critical thing I suppose that may allow to use wallhacks or other cheats) and mark it as unavailable somewhere in a hash table. If a file isn't found now it's not gonna be found later I suppose. Even better to somehow include this situation into the consistency check procedure to catch these errors early so that the player or mapper would verify their game cache or fix the error in their map. I mean, if the resource file should be there but was not found, the game should not allow me to play, right? :/
  • SamusDroidSamusDroid Colorado Join Date: 2013-05-13 Member: 185219Members, Forum Moderators, NS2 Developer, NS2 Playtester, Squad Five Gold, Subnautica Playtester, NS2 Community Developer, Pistachionauts
    edited December 2014
    model: seasonal/holiday2012/models/xmas_rock_mid_str_128.model. coords: -157.510056 2.689704 13.605865
    I printed the model and origin of every model on load and it is where the tunnel is apparently, which is nowhere near water production,
    yzEEOoz.png but you can't select the model because it isn't there. What is interesting is that if you append a . onto the end of a model path in the editor it doesn't make the model disappear, it works like normal and it's still there. :-?
  • rkfgrkfg Russia Join Date: 2013-09-03 Member: 187744Members, Reinforced - Supporter, Reinforced - Silver, Reinforced - Gold, Reinforced - Diamond, Reinforced - Shadow
    This probably has something to do with the way Windows treats file paths. It has several stupid limitations both on allowed characters and the form of the file/folder name. Like it doesn't allow the folder name to start with period so the GIMP profile/data folder can't be deleted from the Explorer as it's called ".gimp-2.8". You can create files with the name starting with period though, and it makes this limitation even more stupid.

    On Linux, however, there are no such restrictions except that you're not allowed to have 0x00 char and '/' (slash) in the filename (true for Windows as well). Everything else is allowed until it fits in the max filename length.

    Probably, Windows just drops the period in the end of the filename as it looks like an empty extension. I've tried this on a virtual machine and it seems to be true. Try it yourself: notepad c:\autoexec.bat — opens that file. Then try notepad c:\autoexec.bat. and get the same file opened. So while the filenames are indeed completely different from the technical point of view, some OSes silently modify them to their liking. I personally very against this as it leads to sorts of hidden bugs like this one and while it doesn't reveal itself on Windows, it's still a bug. Like, if you write a crossplatform software and add the time to some filenames like cache in the form of "HH:mm:ss" and colons are prohibited on Windows so your cache doesn't actually work there (and causes slowdowns) but works on Mac/Linux. A clumsy example, yea, but it shows what can happen.
  • develdevel Join Date: 2014-09-13 Member: 198444Members
    rkfg wrote: »
    If a file isn't found now it's not gonna be found later I suppose. Even better to somehow include this situation into the consistency check procedure to catch these errors early so that the player or mapper would verify their game cache or fix the error in their map. I mean, if the resource file should be there but was not found, the game should not allow me to play, right? :/

    I think that it acts that way to simplify modding. The game can apply changes to some resources on the fly.
  • SamusDroidSamusDroid Colorado Join Date: 2013-05-13 Member: 185219Members, Forum Moderators, NS2 Developer, NS2 Playtester, Squad Five Gold, Subnautica Playtester, NS2 Community Developer, Pistachionauts
    edited December 2014
    So if you print out the coords of model through lua when is it loaded, it prints out -157.510056 2.689704 13.605865. Doing a string.gsub(values.model, "seasonal/holiday2012/models/xmas_rock_mid_str_128.model.", "models/props/eclipse/eclipse_big_generator_fx.model") it replaces the model with one that is easy to find and yJ1BBBc.jpg
    is...actually at -6201.18; 105.89; 535.66. (Didn't think to consider the meter>inch conversion).
    But as expected... the model path for the model in the editor is "seasonal/holiday2012/models/xmas_rock_mid_str_128.model."

  • LokiLoki Join Date: 2012-07-07 Member: 153973Members, Forum Moderators, NS2 Playtester, Squad Five Blue, Squad Five Silver, Squad Five Gold, NS2 Map Tester, Reinforced - Shadow, WC 2013 - Shadow, Subnautica Playtester, NS2 Community Developer, Pistachionauts
    ok, big thanks to samus ive located the offending model and fixed it

    this fix will be in 272
  • NordicNordic Long term camping in Kodiak Join Date: 2012-05-13 Member: 151995Members, NS2 Playtester, NS2 Map Tester, Reinforced - Supporter, Reinforced - Silver, Reinforced - Shadow
    Loki, putting models 6000 units away for fun. Classic loki!
Sign In or Register to comment.