Seemingly random soft-locks while creating large modules

[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.