Seemingly random soft-locks while creating large modules

[Sterno]

I'll start off by saying that I've created quite a few modules (for personal use) in Fantasy Grounds, and most have 5+ MB DB files. I never ran into this issue when using FGC to create modules, but when I switched to using FGU in January of this year while I was creating the OSRIC for 2E module, I started noticing as I was entering NPCs that I'd be typing or scrolling or clicking a tab or something and suddenly Fantasy Grounds would become unresponsive. I'd get kind of a white overlay with a spinning blue wait symbol, as is typical for Windows when an application isn't responding. It typically would resolve itself in 10-20 seconds, though I've had some go for close to a minute.

I was creating this in the 2E ruleset (though I doubt that matters), and the only extension I had enabled was Author, though I did try to disabling that to see if it made a difference, and it did not. I completed the conversion of the OSRIC stuff, shrugged my shoulders, and thought it might be a one-off case.

Then I began a project to convert The Halls of Arden Vul (a 1100+ page megadungeon) for me to use in Fantasy Grounds. I started with new items, spells, etc, and I wasn't hitting any of those soft locks. Then I added some NPCs and the database was creeping up towards around 5 MB, and I started seeing an occasional small one. Now I've started adding the stories/encounters/parcels/tables for the actual dungeon rooms and my DB is up to 13 MB, and when I'm working I probably experience 3-4 of these soft locks an hour, and they usually take 15-45 seconds. After a long session of working, closing the application is particularly slow, too. I figured maybe it's slow because it's writing out the DB changes, but I don't know. When I manually /save, sometimes it's very slow and takes 30+ seconds. Other times it takes about 5 seconds.

I've got a pretty beefy gaming PC with a lot of RAM and I'm working off a m2 drive, so I doubt it's a memory or hardware-based IO speed issue.

I ran OBS earlier tonight just to record it happening, though OBS didn't capture the white overlay and wait cursor, so it's hard to see much going on (though I do verbally note when it starts and ends, and you can kind of see it jump back to life when the freeze ends). Timestamped video of when it occurs here: https://www.youtube.com/watch?v=qXV9y2N6hkM&t=1185s

I'm curious if this is a known issue or if other people have run into it. Asking around in the #dnd_classics_2e discord channel, most people said they haven't seen it, but most are also dealing with smaller DB files of < 5 mb.

It's minor enough that I can just alt-tab out when it happens and check the news or something while I wait for it to unlock, but it is pretty frustrating and can really break the flow when I'm developing content.

[Zarestia]

Autosave happens every 5 minutes. I'm getting 5 seconds hiccups when creating my adventure (3.4 MB atm).

Others have reported similiar things, it gets really irritating when it's not in a dev but actual campaign with players. Fingers crossed this hopefully can be enhanced or a compromise can be found.

[Sterno]

I thought about auto save but the lock definite isn’t happening at regular 5 minute intervals, so I assume there’s have to be more to it than that.

It would track with a manual save sometimes being very slow and other times being quick, though.

[jharp]

One performance detail I've run across in my extensions is that the DB routines do not like long lines. So if you look in your db.xml and see any lines over 20k characters try your best to lower these. I found that if you save a single DB entry of 84k characters the save is several 5+ seconds but with 84 1k entries its less than 1/2 second to save. Also, a 15k character entry saves 10 times faster per character than does a 85k character entry.

I doubt this is the cause but the DB routines most certainly perform better with more smaller lines than with less larger lines.

Jason

[Moon Wizard]

As others have mentioned, I have not seen this; but might have to do with the size/volume of data as @jharp suggested. Given the randomness of the soft locks, I would also guess that they coincide with some memory garbage collection or paging.

I can look at your campaign, just to see if I can recreate; but may be difficult given the lack of specific steps.

Also, you can try running the Windows task manager while running to see memory usage to see if that gives any clues.

Regards,
JPG

[Sterno]

I can send it to you, but I agree it might be a waste of your time given its seeming randomness. The video I recorded that it happened in I made specifically because I wanted video evidence befoire posting the bug, and I knew working for a while would make it happen, but even then it took about 20 minutes for it to happen once. I doubt it's a good use of your time to just play around in the campaign for 20-30 minutes to trigger it once.

Although to be clear, I've had this happen in multiple campaigns, and the only common denominator seemed to be that they were all fairly large (>5 MB).

I'll take some screenshots of Task Manager the next few times it happens to see if it gives any clues. I have in the past looked and neither GPU nor CPU were spiking during the hangs, but I'll check out memory usage and Disk usage, or see if there's an abnormal growth in memory use over time.

[Sterno]

I've had 3 hangs since that last post and a series of screenshots isn't worth capturing based on what I've seen so far. They all look pretty much the same... 0% CPU, 0% Disk, 0% GPU, no particular spike in Memory use. Status shows as "Not Responding" in task manager for the duration.

[Sterno]

Continued observation shows that while Disk usage is at 0% during the hang, it usually jumps to 2.3 MB/s for a few seconds after the hang ends. Almost seems like it wants to do a save but the thread is getting blocked or something.

[Moon Wizard]

What kind of disk are you running on for the FG data folder? (mechnical, SSD, network, USB, ...)
Do you have any file synching software running that might be synching the FG data folder?

Regards,
JPG

[Sterno]

It's running on the same drive as the OS, which is an m.2 drive (1TB GIGABYTE AORUS (PCIE GEN4) NVME M.2 SSD).

I do use some file backup software (Google Drive), but only to one specific folder (and subfolders) that I only add/remove files from manually, so that wouldn't be happening while running FGU and doesn't affect the FGU folders. I'll run with that software disabled just to rule it out, though.

No anti-virus or anything like that running, either, other than whatever Windows 10 is doing by default.

Usually have Discord running at the same time, as well as a browser window on another monitor that's watching Netflix or Twitch or something, as well as Adobe Reader open in the background (since I'm cutting and pasting data from PDFs into FG). I guess I usually have Steam idling in the background too, though this isn't related to it downloading patches or games at the same time or anything.

If I'm the only one experiencing this problem, I can live with it. I'm mainly curious if other people who deal with large DB sizes are experiencing the same thing or not.

I'll also take a look at installing FGU on my work laptop (much less beefy, but much less other stuff installed or running on it) and doing some campaign work there to see if the same problem occurs on different hardware.

[jharp]

If you want to post a link to a copy of your campaign to my DM i'll see if I can reproduce and then I'll post anything I can see that might be an issue.

Thanks I got the file. The only real lag I've been able to get relate to image size memory freeing. It hangs a bit. Nothing like you have mentioned. I'll keep playing at it over the next while and see if I can find anything.

Jason

[Laerun]

There was some chatter about some performance hits recently, and I know that Smiteworks was trying to pin them down. Do you happen to have a ton of sources open and numerous tokens or images in your current campaign? I have also had this happen as well. This is common, but they are not nearly as bad as before. Also, try to look into video card settings, hard drive space, and such. Anti-virus too, as they can scan for changes being made in real-time. Discord is the worse for me... It is a resource hog.

Laerun

[Sterno]

I do have some big images in the campaign, but typically they’re not open or being interacted with when I’m creating items/spells/npcs/parcels/encounters.

I also have a huge assets collection that is slow to search, but again, it’s rarely open or being searched. Really just when I’m adding a token to a NPC.

I already talked about hardware and background software earlier in the thread. I have 32 MB of RAM, a RTX 2080 ti, and a 1 TB m2 drive that’s about half empty. Anything is possible, but I doubt it’s a hardware issue.

[Moon Wizard]

Does it seem to happen about five minutes or so after you do a bunch of stuff in the Assets bag?

Regards,
JPG

[Sterno]

I'll keep an eye out for that Moon. Looking through the video I posted where I recorded it happening (at about 19 minutes in), though, the only time I opened assets was about 17 minutes prior.

[Sterno]

Update: It does not seem to be related to having recently used the Assets bag.

[Moon Wizard]

Just double-checked and the asset release time is 10 minutes for any assets not actively being used by a window in the tabletop.

I'm guessing that it's some sort of garbage collection or save stall based on the fact that it appears to be tied to data; but those are very general concepts. I guess I could add a save timer to the save routine in a future version to at least capture how long a save took, and whether that's where to look further.

Regards,
JPG

[jharp]

Moon,

For this campaign an os.time() on either side of the save is 4-5 seconds.

Jason

[Sterno]

Edit: Nevermind previous version of this comment, looks like UnityCrashHandler is always running in the background.

[Moon Wizard]

If you use the Compile Logs button in the console, it will also pull the Unity Player.log which may or may not have information on what is happening when it hangs (should be at end of file, if you pull logs right after it happens)

I also noticed that you are running right at 4GB of memory in that campaign. I wonder if there is some sort of memory paging going on due to the size in memory. How much other memory is being used by other apps when it happens?

Regards,
JPG

[Sterno]

Using 30-40% of my total memory, depending on what I have running in the background. Nothing seems to be spiking up during those hangs. Also just restarted and memory usage dropped back down to 2.3 GB after restart. When it hit a hang, I was up to 2.8 MB, though to be clear, that was a gradual increase over time as I kept working, not a big jumping spike during the hang.

Compiled and attached logs right after the most recent hang. Timing does seem to match when one of the the autosaves happened (but it definitely isn't hanging regularly every 5 minutes). In this case, I'd been working for about 30 min before a big hang. I wonder if it just has to do with taking certain actions during that window of time where autosave is happening in the background, which would explain why as the DB gets bigger and autosave takes longer, this seems to happen more frequently.

[Trenloe]

Just curious, sorry if it's been mentioned before, does the issue happen to the same level with the UI scale set to 100%?

[Sterno]

Good question. I'm on a 2560x1440 monitor so I usually crank it to 125 or 150 uiscale when developing so I don't go blind.

I'll try it at 100 for a while and see.

[Sterno]

Been watching this closely the last couple days and can say for sure it seems tied to autosave in some way. The hangs always occur at the same time as an autosave. Player.log always has a "Campaign saved." event logged right at the same time the hang ends.

[Moon Wizard]

Yeah, it's just odd that it doesn't occur on every auto-save; since we would think that it should be performing the same behaviors every time (at least the code is supposed to behave that way).

Regards,
JPG

[Sterno]

As my DB.xml has gotten bigger over the weekend (now up to 18.5 MB), it's actually rarer for the hang to NOT occur during the autosave than it is to see it happen. Also, it happens pretty frequently now if I've been working for a while and manually save (even if it just autosaved), though smacking the /save command a bunch of times in a row yields unpredictable results. For instance, after working for about 30 minutes, I just did 5 /save's in a row and four of the five hung. I also just tested opening Fantasy Grounds fresh, loading the campaign, and immediately hitting save, and I got the hang on the first try.

I'll upload the latest version of this campaign to that same Google Drive I PM'd you earlier, since now it might be easier to reproduce.

Right now, the end result is every 5 minutes or so, the app hangs 30-60 seconds for me. The hang time seems to be getting longer too. I'm guessing that the autosave is at the client level and there's no way for me to tweak the timing of it on my end via extension or otherwise?

[Moon Wizard]

I think you're going to have to break up that campaign into separate modules. I don't believe there's not a single adventure in our store that has a 18.5MB db.xml file.

Regards,
JPG

[Ckorik]

This happens to me quite often just playing the games - usually on open of a new item or filtered field (opening spells for example) - doesn't seem to happen opening reference manuals - more just anything that has to sort or filter. It never happens until I load all my content - I just assumed it was known about - I too run off an M.2 drive (512 gb - samsung 850 pro) 32 gb ram 6800xt - same thing as to resources - the rest of my machine runs fine - although I can't use discord if FG is the active window - I have to click outside of FG to use discord when it happens. I could take video if it helps

[celestian]

I think you're going to have to break up that campaign into separate modules. I don't believe there's not a single adventure in our store that has a 18.5MB db.xml file.

Regards,
JPG

AD&D MM is 20M
Night Below is 21M
Temple of Elemental evil is 12M

That's not compressed in a .mod file, but the file before export.

[jharp]

Moon,

I've dug deep into this slowdown and I've found that there are 4 functions in the save path that are responsible for 70-80% time spent saving to db.xml. In my testing the original save routines take 8.7s. I can get this down to less than 3s (more often than not 2.5s or less). In each case the function uses "text += c.ToString();" or similar on a single character. The Concat of a single character is very costly operation wise.



public static string PPOHPFJPMNH(string LOBBPCAMNMN)
{
string text = string.Empty;
foreach (char c in LOBBPCAMNMN)
{
if (c > '\u007f' || c < ' ' || c == '"' || c == '<' || c == '>' || c == '&')
{
string str = text;
string str2 = "&#";
uint num = (uint)c;
text = str + str2 + num.ToString() + ";";
}
else
{
text += c.ToString();
}
}
return text;
}

public static string ODAKNCKJOBB(string LOBBPCAMNMN)
{
string text = string.Empty;
foreach (char c in LOBBPCAMNMN)
{
if ((int)c > -21 || c < 'c' || c == '7' || c == '$' || c == 'p' || (int)c == -39)
{
string str = text;
string str2 = "";
uint num = (uint)c;
text = str + str2 + num.ToString() + "leftlow";
}
else
{
text += c.ToString();
}
}
return text;
}

public static string IJJPNPDMCIM(string LOBBPCAMNMN)
{
string text = string.Empty;
for (int i = 0; i < LOBBPCAMNMN.Length; i++)
{
if (LOBBPCAMNMN[i] == '\r')
{
text += "\\r";
}
else if (LOBBPCAMNMN[i] == '\n')
{
text += "\\n";
}
else if (LOBBPCAMNMN[i] == '\\')
{
text += "\\\\";
}
else
{
text += LOBBPCAMNMN[i].ToString();
}
}
return text;
}

public static string DEKGFIBPNBA(string LOBBPCAMNMN)
{
string text = string.Empty;
bool flag = true;
foreach (char c in LOBBPCAMNMN)
{
if (flag)
{
if (LOBBPCAMNMN.Length > 2 && LOBBPCAMNMN.Substring(0, 3).Equals("xml", StringComparison.InvariantCultureIgnoreCase))
{
text += "_";
}
else if (c >= '0' && c <= '9')
{
text += "id-";
}
else if (!char.IsLetter(c) && c != '_')
{
text += "_";
}
flag = false;
}
if (char.IsLetterOrDigit(c) || c == '-' || c == '_' || c == '.')
{
text += c.ToString();
}
}
return text;
}


If you replace PPOHPFJPMNH and IJJPNPDMCIM with the code below you can save this campaign in under 3 seconds. In my opinion the functions are equivalent in result.



public static string IJJPNPDMCIM(string LOBBPCAMNMN)
{
string text = string.Empty;
int curPos = 0;
int lastSafePos = -1;
for (int i = 0; i < LOBBPCAMNMN.Length; i++)
{
char c = LOBBPCAMNMN[i];
if (c == '\r')
{
if (lastSafePos > -1)
{
text += LOBBPCAMNMN.Substring(curPos, lastSafePos - curPos + 1);
lastSafePos = -1;
}
text += "\\r";
curPos = i + 1;
}
else if (c == '\n')
{
if (lastSafePos > -1)
{
text += LOBBPCAMNMN.Substring(curPos, lastSafePos - curPos + 1);
lastSafePos = -1;
}
text += "\\n";
curPos = i + 1;
}
else if (c == '\\')
{
if (lastSafePos > -1)
{
text += LOBBPCAMNMN.Substring(curPos, lastSafePos - curPos + 1);
lastSafePos = -1;
}
text += "\\\\";
curPos = i + 1;
}
else
{
lastSafePos = i;
}
}
if (lastSafePos > -1)
{
text += LOBBPCAMNMN.Substring(curPos, lastSafePos - curPos + 1);
}
return text;
}

public static string PPOHPFJPMNH(string LOBBPCAMNMN)
{
string text = string.Empty;
int curPos = 0;
int lastSafePos = -1;
for (int i = 0; i < LOBBPCAMNMN.Length; i++)
{
char c = LOBBPCAMNMN[i];
if (c > '\u007f' || c < ' ' || c == '"' || c == '<' || c == '>' || c == '&')
{
if (lastSafePos > -1)
{
text += LOBBPCAMNMN.Substring(curPos, lastSafePos - curPos + 1);
lastSafePos = -1;
}
string str3 = text;
string str2 = "&#";
uint num = (uint)c;
text = str3 + str2 + num.ToString() + ";";
curPos = i + 1;
}
else
{
lastSafePos = i;
}
}
if (lastSafePos > -1)
{
text += LOBBPCAMNMN.Substring(curPos, lastSafePos - curPos + 1);
}
return text;
}



I suspect there are a number of other areas where strings are repeatedly using Concat on a single character.


Thanks,
Jason

[jharp]

With the fixes put in place in 4.1.9 (reduces it to 3-4 seconds) and the above changes it is now less than 1.5 seconds and sometimes as low as 0.7 seconds.

In fact it is a repeating pattern (which concerns me somewhat). First save is 1.2s, next is 0.7s, next is 1.2s, next is 0.7s (repeating).



Jason

[Sterno]

I don't know if that's running for every string being saved or some small subset, but if it's all and it's iterating over every character in strings so that it can do character replacement/appending/encoding or whatever it's doing there, that would definitely explain why save is so slow.

[jharp]

The four functions iterate over a large subset (or complete set) of characters in the save.

[Sterno]

Kind of curious how string.replace or RegEx.replace would perform, too.

Are you just decompiling this, jharp?

[jharp]

I'll give those methods a try and see. I wanted to keep it simple as an immediate patch. I have to avoid questions on the second topic. They are close but ultimately slower. I'm sure its a bit of a coin toss depending on the data set.

Jason

[Moon Wizard]

Those are helper functions, because the built-in XML functions have some interesting default behaviors that won't work for FG data saving in all cases. The ones jharp found are some of the last that hadn't moved to StringBuilder behaviors. They were originally for a small subset, but are also used for formatted text (which is what I think is the slowdown in your case due to the huge volume of formatted text not seen in simpler modules).

I hesitate to change them ad-hoc without a lot of testing, because it affects the save files and data. I already tried looking at the built-in XML encoding routines again, but they handle control characters in a way that we can't use. Also, we probably don't want to use String.Replace, because that creates a lot of dangling string resources that have to be garbage collected, creating a different delayed bottleneck. Since StringBuilder is a drop-in change that doesn't change the logic and we have some StringBuilder caching already, I was going to try swapping that in, and see how it affects save time in that campaign.

However, right now, my hands are busy with some other stuff that has to be done over the next couple weeks, before circling back to any client fixes. Plus, I was deep in a ruleset project before I got pulled away. Thus, why we're hiring. Not enough hands for all the work.

Regards,
JPG

[Sterno]

Just wanted to update this thread, since I know there were some client changes since I last commented on it.

Things have improved since my report in September. Saves times can be quite fast on my large db.xml, currently at 19.7 MB. Some save times are even reported as 0.2s, whereas it used to be 5 seconds minimum!. Whereas it had gotten to the point where if I was actively working, the freeze every 5 minutes was almost guaranteed, now I'd say I see it occur maybe 3-4 times per hour. When it does happen, though, I'm still seeing nearly 1 minute freezes. The freezes all still seem to be tied to when the autosave occurs.

My hypothesis, unproven, is that if I'm taking certain actions while the autosave occurs, I end up in that freeze state. Dragging records into a story or opening a new record often seems to be the action I'm in the middle of taking when a freeze occurs. With the save time having been greatly reduced, I think the window of time in which that conflict can occur has been reduced, but when it does occur, the freeze seems to last well past however long the save would take.

So, still a problem, and still happens enough that I'm just going to bite the bullet and break my mega module up into a bunch of pieces, but it has definitely improved.

[Trenloe]

When it does happen, though, I'm still seeing nearly 1 minute freezes. The freezes all still seem to be tied to when the autosave occurs.
After the freeze, please open the console (type /console in the chat window) - how long does the auto save entry in the console log indicate the save took? You should see something like [<timestamp> 10:33:32 AM] Campaign saved. (0.1s)

[Sterno]

After the freeze, please open the console (type /console in the chat window) - how long does the auto save entry in the console log indicate the save took? You should see something like [<timestamp> 10:33:32 AM] Campaign saved. (0.1s)

Was just working on this module. All I was doing was going through NPCs and finding tokens to set on them. Typically only had open the Assets window, the NPC list, and one NPC record at a time (as I was dragging assets over to their token slot).

1. Started up campaign at 9:05:34 AM and began working.
2. At 9:10:34 AM, per the console, autosave took 0.6 seconds to save. No hang at that time.
3. At 9:16:11 AM, per the console, autosave took 37 seconds to save. Coincided with a hang.
4. Ran a manual save after the hang. Took 0.6 seconds.

Update: While continuing to work, ran into more hangs.

At 9:21:12 AM, 1.2 second save time.
At 9:31:14 AM, 0.6 second save time.
At 9:36:29 AM, 14.8 second save time. (hang)
At 9:41:30 AM, 0.6 second save time.
At 9:46:30 AM, 0.6 second save time.
At 9:52:24 AM, 54 second save time. (hang).
At 9:57:25 AM, 0.6 second save time.
At 10:03:19 AM, 53.5 second save time.

Later today I'll just leave the campaign running in the background without interacting with it and check the console after a few hours to see if the lag spikes only happen during autosave if you're actively working on it, or if it can happen even without interaction.

[Sterno]

After finishing working on the module this morning (but not closing Fantasy Grounds), I just let it run idle in the background while I did other things on my PC.

After an hour of idling, the highest save time is 1.3 seconds.

10:08 0.6s
10:13 0.6s
10:18 1.3s
10:23 0.7s
10:28 0.7s
10:33 1.3s
10:38 0.6s
10:43 0.6s
10:48 0.7s
10:53 1.2s
11:03 0.6s
11:08 1.3s
11:13 0.6s
11:18 0.6s

Definitely appears as if the hangs are related to being active in Fantasy Grounds when autosave kicks off.

[Weissrolf]

I reported a reproducible way of seeing Autosave break FGU's memory management (and thus likely other things) when FGU is *busy* during Autosave. But we will soon read that this is a whole different case and thus not related in any shape or form. And thus you are on your own to prove that Autosave has anything to do with your issues. Not big pictures to be seen here, only case by case studies.

Good luck!

[Moon Wizard]

@Sterno,

I'm wondering if this is more related to using the Assets window, then to the other activities. Do you see any of the delays when entering information without using the Assets window?

Also, how many files and what is the overall size of the Assets in your Data and Campaign images/tokens folders?

Regards,
JPG

[Sterno]

Yes, I definitely see it in cases where I never even open the Assets window during that entire session of FG. The day I was logging times was actually unusual in that I was specifically updating tokens on NPCs. Usually I don't need to worry about that because they're already set up. Next time I work on it I'll log some numbers without opening Assets.

As far as size, though, I do have two large asset modules which make up the bulk of my images. I've got a FGMapmaking.mod file (3.46 GB) which is basically a bunch of Forgotten Adventures mapping assets. I rarely use it so probably wouldn't miss it if I remove it. I've also got a tokens module (all tokens from Forgotten Adventures, plus a few others) that's 1.6 GB. I'd definitely miss that one if I removed it.

I'll try removing the 3.46 GB module and see if it improves things.

As far as the actual "tokens" or "images" folders themselves though, the top-level ones have less than 20 images for < 6 MB of data. The campaign images folder has 192 MB of images across 102 files, about half of which are maps and the other half being some cut and paste art from the module to display to players as handouts.

[Sterno]

Just wanted to update since I hadn't worked on the module in a few months but did again the last few days. Trimming my tokens folder way, way down did not impact performance.

I doubt it's a FOW issue either, since this is a development module and I haven't actually put any tokens on any of the maps. And I'm not sure that would explain the inconsistency of the length of save times, anyway.

When left to idle, autosave is quick. I left it idling for 6 hours and every single autosave varies from 0.6 seconds to 1.2 seconds. When actively working on it and an autosave hits, I'm often seeing autosave times of about 50 seconds (though occasionally they're quick).

[Weissrolf]

Would be nice if Smiteworks would also give us an update what steps they have taken to solve this?