New API Update: Sheet Worker Support in API Scripts, Speed Improvements

I am one of those extreme cases that was feeling the pain.  It is much better now.  Thank you!

Riley D. said: There's also an additional update which is currently only on the Dev API server which should prevent a bug from occurring where API commands would sometimes be re-run if you were sending chat messages with the noarchive: true flag when you re-started your sandbox. I cannot wait for this update to get pushed to live servers! I hate not being able to use noarchive and having so much clutter on the screen between games.

Riley, I don't know what you did about setting (not using setWithWorker()) attributes, but setting attributes is now lightning-fast, as it should be, instead of taking roughly 70 ms per iteration. Very nice!

More speed means more abilities we can shove in there to fill up the bandwidth! Yay ! really everything feels faster and faster the past few months. thanks for all your optimization work.

Kyle G. said: Riley D. said: There's also an additional update which is currently only on the Dev API server which should prevent a bug from occurring where API commands would sometimes be re-run if you were sending chat messages with the noarchive: true flag when you re-started your sandbox. I cannot wait for this update to get pushed to live servers! I hate not being able to use noarchive and having so much clutter on the screen between games. Any timeline on when this comes to Production?

Riley have you seen this? &nbsp;I wonder if it is related to the cacheing recently implemented. It is bizarre: deleting a token that is linked to a character causes the sheetworkers to stop working on that character's sheet. Refreshing the browser fixes it. <a href="https://app.roll20.net/forum/post/4539458/pathfind" rel="nofollow">https://app.roll20.net/forum/post/4539458/pathfind</a>... I suppose we should try it with other character sheets to confirm

Riley D. said: I would check previous versions of the Pathfinder sheet to see if the behavior is still there and other sheets to see if it's happening with those as well. If it is we can dig deeper into it. *snip* Moved to the corresponding&nbsp; thread because it really does not belong here.

Riley D. said: Scott C. said: Kyle G. said: Riley D. said: There's also an additional update which is currently only on the Dev API server which should prevent a bug from occurring where API commands would sometimes be re-run if you were sending chat messages with the noarchive: true flag when you re-started your sandbox. I cannot wait for this update to get pushed to live servers! I hate not being able to use noarchive and having so much clutter on the screen between games. Any timeline on when this comes to Production? Next week. Nice, looking forward to getting my script's menus to no longer be archived.

Jakob said: Riley D. said: I would check previous versions of the Pathfinder sheet to see if the behavior is still there and other sheets to see if it's happening with those as well. If it is we can dig deeper into it. It doesn't seem to have anything to do with the API, but it's definitely happening regardless of sheet. It's easily reproducible for me with this sheet: Strength: &lt;input type="number" name="attr_strength"&gt;, Strength bonus: &nbsp;&lt;span name="attr_strength_bonus"&gt;&lt;/span&gt; &lt;script type="text/worker"&gt; on('change:strength', function() { getAttrs(['strength'], function(v) { setAttrs({strength_bonus: Math.floor((v.strength-10)/2)}); }); }); &lt;/script&gt; Whenever you delete a token representing a character from the tabletop, sheet workers for that character, and only that character, stop functioning. Could this also be related to the proficiency bonus not updating on level up on the OGL sheet?

I finally got around to trying out the new fixes for getAttrByName() in my trap theme scripts. When I use it to try to get a calculated attribute though, it still gives the string expression for the attribute instead of the resolved value. Here is my code: /** &nbsp; &nbsp; &nbsp;* Asynchronously gets the value of a character sheet attribute. &nbsp; &nbsp; &nbsp;* @param &nbsp;{Character} &nbsp; character &nbsp; &nbsp; &nbsp;* @param &nbsp;{string} &nbsp; attr &nbsp; &nbsp; &nbsp;* @return {Promise&lt;any&gt;} &nbsp; &nbsp; &nbsp;* &nbsp; &nbsp; &nbsp; &nbsp; Contains the value of the attribute. &nbsp; &nbsp; &nbsp;*/ &nbsp; &nbsp; static getSheetAttr(character, attr) { &nbsp; &nbsp; &nbsp; /* &nbsp; &nbsp; &nbsp; let rollExpr = '@{' + character.get('name') + '|' + attr + '}'; &nbsp; &nbsp; &nbsp; return TrapTheme.rollAsync(rollExpr) &nbsp; &nbsp; &nbsp; .then((roll) =&gt; { &nbsp; &nbsp; &nbsp; &nbsp; if(roll) &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; return roll.total; &nbsp; &nbsp; &nbsp; &nbsp; else &nbsp; &nbsp; &nbsp; &nbsp; &nbsp; throw new Error('Could not resolve roll expression: ' + rollExpr); &nbsp; &nbsp; &nbsp; }); &nbsp; &nbsp; &nbsp; */ &nbsp; &nbsp; &nbsp; let value = getAttrByName(character.get('_id'), attr); &nbsp; &nbsp; &nbsp; log(attr); &nbsp; &nbsp; &nbsp; log(value); // Expected to get the resolved numerical value. &nbsp; &nbsp; &nbsp; return Promise.resolve(value); &nbsp; &nbsp; } Here is an example of the logging output I got: "wisdom_save_bonus" "(@{wisdom_mod}+@{wisdom_save_prof})"

Hey all, Have finally got round to looking at this again. Things seem to working much better than the last time I played with it, which is great. I am getting one strange error in certain circumstances: TypeError: Cannot read property 'get' of undefined TypeError: Cannot read property 'get' of undefined at Worker.onmessage (/home/node/d20-api-server/api.js:2775:50) at ChildProcess.&lt;anonymous&gt; (/home/node/d20-api-server/node_modules/tiny-worker/lib/index.js:39:21) at emitTwo (events.js:100:13) at ChildProcess.emit (events.js:185:7) at handleMessage (internal/child_process.js:695:10) at Pipe.channel.onread (internal/child_process.js:440:11) I can't pinpoint exactly when this is happening, because it seems to disrupt the logging somehow - I have had immediately sequential logging statements in the one method and only the first one outputs before the error - since AIUI the API/sheetworkers are single-threaded, I guess the log messages are in some sort of queue that doesn't get flushed properly when an error occurs. Anyway, by dint of some trial and error I have determined one thing that I can do to prevent the error from happening - I can comment out a call to removeRepeatingRow in one part of the sheetworker code. I have no idea why this should be! Questions: What is undefined in Worker.onmessage line 2775? Is this an internal error/oversight in the new code to execute sheetworkers under the API, or is it a cryptic report of an error inside the sheetworkers themselves? If the latter, is there any chance of getting some more helpful error information? Without either reliable synchronous logging or stack traces, these problems are essentially impossible to debug :-( Thanks!

Lucian said: If the latter, is there any chance of getting some more helpful error information? Without either reliable synchronous logging or stack traces, these problems are essentially impossible to debug :-( This 1000 times. It's a problem with the API as well. The new (as of a few weeks ago I think) error reports are practically useless in finding where the error was thrown from, especially when they state that the error comes form a completely different, and unrelated script.

Riley D. said: There was an error with the API implementation of the removeRepeatingRow() function which apparently wasn't caught during testing on Dev. I included a fix for this in the update that was just pushed out so the error should be resolved. To answer your questions re: logging, anytime you see an error where the last step of the stacktrace is in "api.js", that's an error outside of the API sandbox that your scripts don't have access to, so logging wouldn't work there anyway. It would indicate that either a) you passed in something seriously different than what the API was expecting for a function call and so it bailed, or b) there is a bug with our implementation of something (which is what occurred here). If it's an error with your own scripts, you should see the stacktrace containing "apiscript.js". Awesome, thanks Riley, that's fixed it. Thanks for the info about the logging as well - I suspected that there might be a problem in the framework code but I wasn't sure if either (a) it was the sheetworkers breaking some important assumption somewhere or (b) perhaps the way the errors were caught and reported was hiding their original source. Good to know how I can identify it for the future!

I'm getting very close to completing the conversion of the Shaped Companion script to use setWithWorker now. Mostly, everything is working fine, but I think we still may have one tricky problem with timings/timeouts/performance. If I set a handful of attributes at the same time, then onSheetWorkerCompleted is generally called at what seems like an appropriate point. Unfortunately, in some cases, I'm trying to set quite a lot of attributes at once (~300) - this in a case when I'm populating a repeating section with e.g. spells for a character. What *appears* to be happening is that most of the time, the callback comes almost immediately - before any of the sheetworkers have really started executing according to my logging. It's almost like there's some expensive calculation that's happening right at the start (perhaps working out which workers to fire?) which scales badly with the number of attributes set at once. As a result, when you set lots of attributes that can trigger sheetworkers in one batch, the timeout for checking on sheetworker activity gets eaten up before the sheetworkers even start properly.... Would it be possible to start the timeout from the point that the last sheetworker in the original batch (not including dependent updates) fires, to avoid this problem? Or optimise the code that fires the sheetworkers to remove the delay? Would that make any sense? I'm trying to construct a minimal testcase for you but it might be quite difficult :-/ Was hoping maybe that there was something obvious that would jump up at you from looking at the code in conjunction with the above...

Just to throw a bit of extra information into the mix that appears to confirm my suspicions - if I split my attribute array into groups of 50 and set those sequentially, it works as expected - so it definitely does seem connected to the number of attributes being set / batch.&nbsp; FWIW, the campaign in question is very small, so I don't think it's connected to overall object count.

maybe, if it's not a system problem, the way to do it is to use the regular set attribute that will not fire sheetworkers to set all the values, then in the callback returned from that use setWithWorker to check a "recalculate/total/something repeating list" checkbox watched by a sheetworker, which will recalculate the values needed and then reset the checkbox. That is basically what we have to do on the pathfinder sheet even with sheetworkers, I have to use silent:true when i call setAttrs quite often, and then call other functions that set totals,etc in the callback.

@Chris b. - yeah, I think we may eventually move to more silent:true stuff with manually triggering... but it would be nice if the chained stuff worked properly under the API as well! @Riley - I've realised that there's another thing that I don't think we've thought of here: what about .remove() ? This also has the potential to do something monitored by sheetworkers but AFAIK this doesn't get fired at the moment...

chris b. said: That is basically what we have to do on the pathfinder sheet even with sheetworkers, I have to use silent:true when i call setAttrs quite often, and then call other functions that set totals,etc in the callback. I was planning on doing this quite soon. The fact that you do it is reassuring that it's the right step. Thanks!

Hey Riley, Are you still following this? I've raised a couple of bug issues relating to this stuff now, but I'm not sure what's the best place for the performance question I mentioned. Completely understand if you've got a bunch of higher priority stuff to deal with now, but was just wondering what the best forum/place for it would be now that this feature is not "at the top of the list" so to speak... Cheers,

Hey Riley, Thanks for getting back to me - no trouble about the delay, just wanted to make sure this was still an appropriate place to report things. I've written up the remove issue more fully here: <a href="https://app.roll20.net/forum/post/4618588/api-she" rel="nofollow">https://app.roll20.net/forum/post/4618588/api-she</a>... . In practice, it seems like removing an attribute on the client generates a :change event rather than a :remove event - not sure if this is correct - but at any rate no equivalent event is fired when you remove an attribute via the API. In case you didn't see it, I also found another issue here: <a href="https://app.roll20.net/forum/post/4618223/api-shee" rel="nofollow">https://app.roll20.net/forum/post/4618223/api-shee</a>... Cheers, Lucian

Riley D. said: Okay I have a new API version on Dev that should address both of these issues. The second issue (with the default attribute difference) should just work properly now. There was a bug with the API where it wasn't properly handling the default values for span elements that had the same attribute names as an existing input. Hey Riley, I've finally managed to test both of these - sorry for the delay, there were various other things broken that needed fixing before I could test properly. It looks like both of these are working properly now - thanks so much for sorting these out. I still suspect that there may be some odd things happening around the timeouts (see my comments upthread) but I *think* we can work around these by doing attribute updates in batches for the time being + I believe Kryx is going to be modifying the sheetworkers to make less use of dependent updates which should also alleviate the problem somewhat. Cheers,

Hey Riley, Just ran a big bunch of stuff using API sheetworkers and got this: TypeError: Cannot read property 'substring' of undefined TypeError: Cannot read property 'substring' of undefined at Worker.onmessage (/home/node/d20-api-server/api-dev.js:2795:61) at ChildProcess.&lt;anonymous&gt; (/home/node/d20-api-server/node_modules/tiny-worker/lib/index.js:39:21) at emitTwo (events.js:100:13) at ChildProcess.emit (events.js:185:7) at handleMessage (internal/child_process.js:695:10) at Pipe.channel.onread (internal/child_process.js:440:11) I'm guessing from what you said before that's an error/violated assumption in your code? Cheers, Lucian

&nbsp;Cool, thanks Riley.&nbsp; I thought it was probably something like that. I suspect there's a double-deletion going on somewhere - hopefully with the extra debugging in now it will be easy enough to track down.

Hey Riley, Sorry, got another one for you! :-) Not sure if this a recent introduction or something I just managed to miss. It appears that if you setAttrs({foo:1, foo_max:2}) in a sheetworker, you get two attributes one with the current value populated, and one with the max value populated. Obviously this works fine on the client, but it's reliably broken under the API. Here's a testcase. Sheet: &nbsp;&nbsp;&nbsp;&nbsp;&nbsp; &lt;input type="number" name="attr_myattr"/&gt; &nbsp;&nbsp;&nbsp;&nbsp;&nbsp; &lt;input type="number" name="attr_myattr_max"/&gt; &nbsp;&nbsp;&nbsp;&nbsp;&nbsp; &lt;input type="number" name="attr_triggerattribute"/&gt; &nbsp; &lt;script type="text/worker"&gt; &nbsp; &nbsp;&nbsp;&nbsp; console.info("Hello from sheetworker"); &nbsp;&nbsp;&nbsp; &nbsp; &nbsp;&nbsp;&nbsp; on("change:triggerattribute", function() { &nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; console.info("Trigger attribute heard change"); &nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; getAttrs(['triggerattribute'], function(vals) { &nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; console.info('Trigger attribute value: ' + vals.triggerattribute); &nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; setAttrs({myattr:vals.triggerattribute, myattr_max:vals.triggerattribute * 2}); &nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp;&nbsp; }); &nbsp;&nbsp;&nbsp; }); &nbsp;&nbsp;&nbsp; &nbsp; &lt;/script&gt; Script: on('chat:message', function(msg) { &nbsp;&nbsp;&nbsp; 'use strict'; &nbsp;&nbsp; if (msg.content === '!test') { &nbsp;&nbsp;&nbsp;&nbsp; const graphic = getObj('graphic', msg.selected[0]._id); &nbsp;&nbsp;&nbsp;&nbsp; const charId = graphic.get('represents'); &nbsp;&nbsp;&nbsp;&nbsp; const attribute = findObjs({ type: 'attribute', name:'triggerattribute', characterid:charId})[0]; &nbsp;&nbsp;&nbsp;&nbsp; findObjs({type: 'attribute', characterid:charId, name: 'myattr'}).forEach(attr =&gt; attr.remove()); &nbsp;&nbsp;&nbsp;&nbsp; attribute.setWithWorker({current: 4}); &nbsp;&nbsp; } }); You can edit the 3rd field on the character sheet on the client and the two previous fields will populate with the copied value and the copied value * 2 respectively. Inspecting the attributes tab shows a single attribute with a current and max value as expected. But when you execute the script with the character selected, you end up with 3 attributes - the trigger and then two copies of 'myattr'. Hopefully it's an easy fix!

Hmm, I'm afraid I've got an addendum to my last report that may make things a little more complicated. It would seem that in addition to the reliable duplication happening when setting max values, there's also a non-deterministic duplication happening in other circumstances. I've done some tracing of this now. There's an attribute 'edit_mode' on the shaped sheet. There are two places in the sheet that set this. One is in a handler for srd content, that I'm absolutely certain isn't being called in any of the cases I'm looking at. The other is in an initialisation function. When I first create a character using the script, I trigger this initialisation function by flipping an attribute. I wait for my sheetWorkerCompleted callback and then I dump out all the attributes that the character now has. At this point, sometimes, but not always, the character now has two edit_mode attributes, both with the same value of 'on'. Looking at the logging that comes out, I'm pretty sure that the function that sets edit_mode has only been called once, because it logs when it finally sets its data, and I only see this once. There are a bunch of other changes that get kicked off from with this function, which all do their own getAttrs -&gt; setAttrs separately and none of them go anywhere near edit_mode. So far I've seen no evidence that this behaviour occurs on the client. The code that caught is some code that asserts the return from findObjs for an attribute returns at most 1 attribute. This code has been around for a while (prior to API sheetworkers) and has never thrown anything up until I started running the sheetworkers under the API. From the evidence I have, I feel comfortable stating: The duplicate attributes are being created during execution of sheetworkers under the API The execution that causes the problem is triggered by a single attribute change which calls a single initialisation function Multiple setAttrs calls result eventually from this single triggered change edit_mode is only explicitly included in a setAttrs call once during this seqeuence edit_mode is never read or requested anywhere in the sheetworkers Given that this happens non-deterministically, I'm wondering if there's some possibility that when executed under the API, data can somehow leak from one callback context to another. When the sheetworkers do setAttrs({edit_mode: 'on'}, ()=&gt;{}), is there some way that the object passed in is somehow not getting cleaned up properly, and is polluting the context for a subsequent setAttrs call? In that situation I could imagine there being two parallel-ish setAttrs calls that are both attempting to set the same attribute (which doesn't exist yet) to the same value - and they both succeed before either of them has a chance to realise that the other is doing the same (not sure how you deal with the synchronisation (or not) of setAttrs turning into a set or a create). But that's obviously wild speculation because I don't know what your code is doing! Hope some of this is helpful, let me know if you want more detail about anything.

Sorry for carpet-bombing the thread, but I need to re-emphasise the fact that we also still have a problem in practice with the timeouts/callbacks, particularly in large campaigns. I recently introduced a feature to my script that creates a dummy character on startup, triggers the basic initialisation of it using a setWithWorker call, waits for the onSheetWorkerCompleted, reads the 'version' attribute, and then deletes the character. This allows me to check that a compatible version of the character sheet is installed to avoid spurious bug reports and other confusion. Unfortunately, it quickly became clear that this feature was causing API crashes for a lot of people. The onSheetWorkerCompleted call was coming back before the sheetworkers were complete, and then things exploded when I deleted the character from underneath them. In a bid to work around this, I put in a setTimeout to delay the deletion of the character, and this fixed it for most people, but there were still a few people getting the problem. It turns out that these were people with big campaigns like SKT - so it looks like we're still dealing with a scaling problem of some sort. For the time being, I've scaled my timeout to the size of the campaign, but the unreliability of this is a worry for the whole system. Although I haven't found it breaking anything yet, I have noticed from my logs that sheetworkers regularly do continue executing after the callback, even in relatively small campaigns; I guess it's only a matter of time before some unpleasant bugs turn up as&nbsp; a result. &nbsp; Looking at the ordering in the logs in this particular case, it would seem that some of the initialisation does complete before the callback comes, but not all of it. If that's right and my understanding of how the timeout system works is correct, that means that one of the intermediate steps of actually running the sheetworkers must be individually taking longer than the API sheetworker callback timeout. But within the sheetworkers, the only operations are getting and setting attributes for an individual character, which should now be indexed/cached and should be more or less constant time irrespective of campaign size. It seems like there must be some non-obvious part of the system that is scaling linearly with campaign size that is dragging the rest of it down...

Thanks Riley! Let me know if there's anything more you need to track stuff down.

Riley D. said: Okay, I've read all of this and will attempt to put in a few fixes when I get a chance hopefully later this week. Hey Riley, Eeeeeeeek! Did I report too many bugs and drive you away??? :-) Are you still likely to be able to do this or do I need to be going through other channels to get these things looked at now? The bug forum seems kinda...dead... at the moment :-( Lucian PS Seriously though, congratulations and best of luck with the new project!

Awesome. Thanks Riley, I will get testing that and recruit some of the Shaped Test Army (TM) to try and break things as well :-)

Initial testing suggests that we've nailed the duplicate attributes thing. I'll need to wait to see if any of the usual suspects can get it to break in interesting ways, but so far I haven't seen any, and even the less common case happened fairly frequently for me before. For onSheetWorkerCompleted(), it looks maybe a bit better... but still far from perfect, sadly :-/ My version tester thing still gets a callback too early - often before even the first attributes have been set by the sheetworkers. I'm guessing that this may have to do with the fact that this is all happening just as the sandbox is first spinning up - which might make things run a bit slower?? After startup, imports generally seem to be cleaner on a normal campaign - I don't get lots of "trailing sheetworker activity" after the callbacks like I used to. On a big campaign, however, I'm still seeing a lot of activity after the callback. I guess I'm going to have to get some better profiling into the sheetworkers to see if I can identify where the delay is.

Ok, so I've done a little bit of basic profiling: "5eShapedCompanion 1488618858086 DEBUG : Campaign size: 73323" "1488618858177 Getting attributes for initialize.sheetOpened" "1488618858579 Got attributes for initialize.sheetOpened" "1488618858580 Processing start for initialize.sheetOpened" "1488618858581 Getting repeating sections for initialize.generateSkills" "1488618858582 Getting attributes for abilities.update" "1488618858583 Getting repeating sections for abilityChecks.updateMacro" "1488618858583 Getting attributes for abilityChecks.updateInitiative" "1488618858584 Getting attributes for savingThrows.updateMacro" "1488618858584 Processing end for initialize.sheetOpened" "1488618858585 Setting attrs for initialize.sheetOpened" "1488618858596 Got repeating sections for initialize.generateSkills" "1488618858596 Getting attrs for repeating sections for initialize.generateSkills" "1488618858604 Got attributes for abilities.update" "1488618858610 Processing start for abilities.update" "1488618858613 Processing end for abilities.update" "1488618858613 Setting attrs for abilities.update" "1488618858616 Got repeating sections for abilityChecks.updateMacro" "1488618858616 Getting attrs for repeating sections for abilityChecks.updateMacro" "1488618858625 Got attributes for abilityChecks.updateInitiative" "1488618858625 Processing start for abilityChecks.updateInitiative" "1488618858626 Processing end for abilityChecks.updateInitiative" "1488618858626 Setting attrs for abilityChecks.updateInitiative" "1488618858633 Got attributes for savingThrows.updateMacro" "1488618858634 Processing start for savingThrows.updateMacro" "1488618858636 Processing end for savingThrows.updateMacro" "1488618858636 Setting attrs for savingThrows.updateMacro" "1488618858662 Finished setting attributes for initialize.sheetOpened" "1488618858670 Got attributes for repeating sections initialize.generateSkills" "1488618858670 Processing start for repeating sections initialize.generateSkills" "1488618858673 Processing end for repeating sections initialize.generateSkills" "1488618858673 Setting attrs for initialize.generateSkills" "1488618858876 Finished setting attributes for abilities.update" "1488618858888 Got attributes for repeating sections abilityChecks.updateMacro" "1488618858888 Processing start for repeating sections abilityChecks.updateMacro" "1488618858889 Processing end for repeating sections abilityChecks.updateMacro" "1488618858889 Setting attrs for abilityChecks.updateMacro" "1488618858912 Finished setting attributes for abilityChecks.updateInitiative" "1488618861755 Finished setting attributes for savingThrows.updateMacro" "1488618862092 Set attributes for repeating sections initialize.generateSkills" "1488618862093 Getting repeating sections for abilityChecks.updateSkill" "1488618862115 Set attributes for repeating sections abilityChecks.updateMacro" "1488618866487 Got repeating sections for abilityChecks.updateSkill" "1488618866487 Getting attrs for repeating sections for abilityChecks.updateSkill" "1488618866670 Got attributes for repeating sections abilityChecks.updateSkill" "1488618866674 Processing start for repeating sections abilityChecks.updateSkill" "1488618866676 Processing end for repeating sections abilityChecks.updateSkill" "1488618866676 Setting attrs for abilityChecks.updateSkill" "1488618867021 Set attributes for repeating sections abilityChecks.updateSkill" "1488618867021 Getting repeating sections for abilityChecks.updateMacro" "1488618871126 Got repeating sections for abilityChecks.updateMacro" "1488618871126 Getting attrs for repeating sections for abilityChecks.updateMacro" "1488618871157 Got attributes for repeating sections abilityChecks.updateMacro" "1488618871158 Processing start for repeating sections abilityChecks.updateMacro" "1488618871159 Processing end for repeating sections abilityChecks.updateMacro" "1488618871159 Setting attrs for abilityChecks.updateMacro" "1488618871337 Set attributes for repeating sections abilityChecks.updateMacro" For reference, the relevant part of the function that kicks this all of is: this.generateSkills(); abilities.updateAll(); abilityChecks.updateMacro(); abilityChecks.updateInitiative(); savingThrows.updateMacro(); generateSkills has a setAttrs callback at the end of it, which calls abilityChecks.updateSkill(). That should be enough to explain the sequencing of the above trace. The first line is output immediately before I set the attribute that triggers the subsequent sheetworker activity. There's a delay of 91ms before the first sheetworker activity, which is a bit on the high side, but not disastrous. What comes next, though, looks like a problem. It takes 402ms to return a simple getAttrs call (requesting 13 attributes, none of which exist yet, I don't believe). Interestingly, the next getAttrs calls all return quite quickly. Is the initial delay the caching of attributes etc happening lazily? If so, when exactly does this happen? Is it a per-campaign thing, or a per-character thing? Happy to introduce a delay to work around it, unless perhaps you can factor this into your timeout calculations for onSheetWorkerCompleted as well? There's then another big delay (200ms) before "Finished setting attributes for abilities.update", and then a HUGE, nearly 3 second delay before "Finished setting attributes for savingThrows.updateMacro". The original setAttrs call for that happened at 58636, and the callback comes at 61755 - which is 3119ms later! As we look further through the trace, there other huge gaps of several seconds. All of the sheet logic/processing happens between the "processing start" and "processing end" lines - and as you can see, this is never more than a few milliseconds. The delays appear to be on stuff returning from the server still. There doesn't seem to be any particular pattern to which calls take lots of time. For example, by the end of the trace, the only thread still going on is abilityChecks.updateMacro). There's a &gt;4s delay (!) simply requesting repeating sections using getSectionIDs with nothing else going on. That's crazy! But other getSectionId calls return in a few tens of ms, so it doesn't look like a systematic problem with that call. Judging by the trace alone, I'd have to guess that either (1) there's a server under unreasonable load somewhere in the system that is just grinding to a halt every few calls and causing everything to back up or (2) there's some sort of expensive, intermittent process that is kicking in on the API sandbox and making everything else wait every so often - perhaps something to do with cache management given that this seems worse for large campaigns? As usual, I'm stabbing in the dark without darkvision here; realistically if we want to solve this properly I think it's going to involve you guys introducing some profiling at your end, because it looks like there are still some very large delays going on there somewhere. Without wanting to teach my grandmother to suck eggs, it's been my experience that attempting to fix performance problems by tweaking the "obvious culprits" without actually profiling the system is almost always a waste of energy; it usually turns out that it's the thing that you least expected that's blocking everything else. Putting the logging in is dull, I know, but it's less dull than playing whack-a-mole with a performance bug that rumbles on for months and months. I'm also aware that a lot of energy has gone into this feature now, which is pro-only and has largely been driven by a few script/sheet authors. Nonetheless, as I said before, a lot of other users do get value out of these scripts/sheets + I'm confident that many of these performance improvements will have an impact on everyone's Roll20 experience - and, in the long run, your hosting bills! So I hope that it will continue to seem worthwhile trying to nail this stuff down! :-) Cheers,

I've realised that I didn't include logging of when the sheetworker callback actually came in my last trace. Here's another trace of the same sequence with that included: "5eShapedCompanion 1488621338351 DEBUG : Campaign size: 73323" "1488621338442 Getting attributes for initialize.sheetOpened" "1488621338781 Got attributes for initialize.sheetOpened" "1488621338782 Processing start for initialize.sheetOpened" "1488621338783 Getting repeating sections for initialize.generateSkills" "1488621338784 Getting attributes for abilities.update" "1488621338784 Getting repeating sections for abilityChecks.updateMacro" "1488621338785 Getting attributes for abilityChecks.updateInitiative" "1488621338785 Getting attributes for savingThrows.updateMacro" "1488621338786 Processing end for initialize.sheetOpened" "1488621338786 Setting attrs for initialize.sheetOpened" "1488621338796 Got repeating sections for initialize.generateSkills" "1488621338796 Getting attrs for repeating sections for initialize.generateSkills" "1488621338804 Got attributes for abilities.update" "1488621338810 Processing start for abilities.update" "1488621338812 Processing end for abilities.update" "1488621338813 Setting attrs for abilities.update" "1488621338816 Got repeating sections for abilityChecks.updateMacro" "1488621338816 Getting attrs for repeating sections for abilityChecks.updateMacro" "1488621338824 Got attributes for abilityChecks.updateInitiative" "1488621338824 Processing start for abilityChecks.updateInitiative" "1488621338825 Processing end for abilityChecks.updateInitiative" "1488621338825 Setting attrs for abilityChecks.updateInitiative" "5eShapedCompanion 1488621341756 DEBUG : Sheetworker callback" "1488621338833 Got attributes for savingThrows.updateMacro" "1488621338834 Processing start for savingThrows.updateMacro" "1488621338835 Processing end for savingThrows.updateMacro" "1488621338835 Setting attrs for savingThrows.updateMacro" "1488621338862 Finished setting attributes for initialize.sheetOpened" "1488621338870 Got attributes for repeating sections initialize.generateSkills" "1488621338870 Processing start for repeating sections initialize.generateSkills" "1488621338873 Processing end for repeating sections initialize.generateSkills" "1488621338873 Setting attrs for initialize.generateSkills" "1488621339077 Finished setting attributes for abilities.update" "1488621339088 Got attributes for repeating sections abilityChecks.updateMacro" "1488621339088 Processing start for repeating sections abilityChecks.updateMacro" "1488621339089 Processing end for repeating sections abilityChecks.updateMacro" "1488621339089 Setting attrs for abilityChecks.updateMacro" "1488621339110 Finished setting attributes for abilityChecks.updateInitiative" "1488621341866 Finished setting attributes for savingThrows.updateMacro" "1488621342184 Set attributes for repeating sections initialize.generateSkills" "1488621342185 Getting repeating sections for abilityChecks.updateSkill" "1488621342206 Set attributes for repeating sections abilityChecks.updateMacro" "1488621346362 Got repeating sections for abilityChecks.updateSkill" "1488621346363 Getting attrs for repeating sections for abilityChecks.updateSkill" "1488621346533 Got attributes for repeating sections abilityChecks.updateSkill" "1488621346537 Processing start for repeating sections abilityChecks.updateSkill" "1488621346539 Processing end for repeating sections abilityChecks.updateSkill" "1488621346539 Setting attrs for abilityChecks.updateSkill" "1488621346853 Set attributes for repeating sections abilityChecks.updateSkill" "1488621346853 Getting repeating sections for abilityChecks.updateMacro" "1488621350732 Got repeating sections for abilityChecks.updateMacro" "1488621350732 Getting attrs for repeating sections for abilityChecks.updateMacro" "1488621350754 Got attributes for repeating sections abilityChecks.updateMacro" "1488621350755 Processing start for repeating sections abilityChecks.updateMacro" "1488621350756 Processing end for repeating sections abilityChecks.updateMacro" "1488621350756 Setting attrs for abilityChecks.updateMacro" "1488621350940 Set attributes for repeating sections abilityChecks.updateMacro" It's interesting to note that the log statement from the API script is inserted in the wrong place according to its timestamp. I don't know if this is an artefact of the way your log messages get queued up from different sources, or if it means that there are some clocks that are out of sync somewhere. Most likely the former, because the timestamp would put the callback just before the first mega-delay, which would make sense. This is probably very late in the day to be asking this, but is there a reason why you don't just intercept all the server calls from the sheetworkers, wrap the callbacks, and "tick them off" as they come back? If there's an "open" call that you're waiting for a return from, the onSheetWorkerCompleted callback should never be called, irrespective of the timeout. Now obviously, I think 4 second delays in calls to get a list of repeating section IDs is still something that needs fixing, but at least with this sort of callback tracking you can have some confidence that the callback will eventually happen at the right time. In fact, if you did this, wouldn't it be possible to dispense with the timeout altogether and have a fully deterministic approach? I'm not 100% clear where the triggering code for dependent updates fits in under the API sheetworkers system, but I would imagine: setWithWorker calls made, callback registered API server updates firebase with new values, detects which sheetworkers need to trigger, executes sheetworkers Sheetworkers do a series of getAttrs - which get intercepted and tracked, waiting for server response Sheetworkers do a series of setAttrs - which also get intercepted and tracked, waiting for server response When setAttrs return, API server checks to see if any other sheetworkers need triggering, if so, trigger from (2) again At the end of each callback, check the list of open callbacks. If it's empty, call with onSheetWorkerCompleted callback, otherwise carry on waiting Obviously all of this could be done most neatly with Promises, but I don't know if that's something you typically use at the moment; it's equally possible without, if a little messier.

BTW, on the performance thing, another observation: the big gaps are always in the same place. So I'm guessing it's not a server load thing.

Ok. I just ran an equivalent test in a browser with the same campaign. I created a new character sheet and opened it. Here's the log, with the Roll20 logging pruned out, and just the same bits that we had above: Triggering for sheet:opened 1488630729419 Getting attributes for initialize.sheetOpened 1488630730554 Got attributes for initialize.sheetOpened 1488630730554 Processing start for initialize.sheetOpened 1488630730555 Getting repeating sections for initialize.generateSkills 1488630730556 Getting attributes for abilities.update 1488630730556 Getting repeating sections for abilityChecks.updateMacro 1488630730556 Getting attributes for abilityChecks.updateInitiative 1488630730557 Getting attributes for savingThrows.updateMacro 1488630730557 Processing end for initialize.sheetOpened 1488630730557 Setting attrs for initialize.sheetOpened 1488630730561 Got repeating sections for initialize.generateSkills 1488630730561 Getting attrs for repeating sections for initialize.generateSkills 1488630730582 Got attributes for abilities.update 1488630730582 Processing start for abilities.update 1488630730584 Processing end for abilities.update 1488630730584 Setting attrs for abilities.update 1488630730621 Got repeating sections for abilityChecks.updateMacro 1488630730621 Getting attrs for repeating sections for abilityChecks.updateMacro 1488630730623 Got attributes for abilityChecks.updateInitiative 1488630730623 Processing start for abilityChecks.updateInitiative 1488630730623 Processing end for abilityChecks.updateInitiative 1488630730624 Setting attrs for abilityChecks.updateInitiative 1488630730625 Got attributes for savingThrows.updateMacro 1488630730625 Processing start for savingThrows.updateMacro 1488630730627 Processing end for savingThrows.updateMacro 1488630730627 Setting attrs for savingThrows.updateMacro 1488630730655 Finished setting attributes for initialize.sheetOpened 1488630730707 Got attributes for repeating sections initialize.generateSkills 1488630730707 Processing start for repeating sections initialize.generateSkills 1488630730709 Processing end for repeating sections initialize.generateSkills 1488630730710 Setting attrs for initialize.generateSkills 1488630730868 Finished setting attributes for abilities.update 1488630731238 Got attributes for repeating sections abilityChecks.updateMacro 1488630731239 Processing start for repeating sections abilityChecks.updateMacro 1488630731239 Processing end for repeating sections abilityChecks.updateMacro 1488630731239 Setting attrs for abilityChecks.updateMacro 1488630731394 Finished setting attributes for abilityChecks.updateInitiative 1488630731586 Finished setting attributes for savingThrows.updateMacro 1488630731987 Set attributes for repeating sections initialize.generateSkills 1488630731988 Getting repeating sections for abilityChecks.updateSkill 1488630732449 Set attributes for repeating sections abilityChecks.updateMacro 1488630732453 Got repeating sections for abilityChecks.updateSkill 1488630732453 Getting attrs for repeating sections for abilityChecks.updateSkill 1488630732466 Got attributes for repeating sections abilityChecks.updateSkill 1488630732466 Processing start for repeating sections abilityChecks.updateSkill 1488630732469 Processing end for repeating sections abilityChecks.updateSkill 1488630732469 Setting attrs for abilityChecks.updateSkill 1488630732895 Set attributes for repeating sections abilityChecks.updateSkill 1488630732895 Getting repeating sections for abilityChecks.updateMacro 1488630733126 Got repeating sections for abilityChecks.updateMacro 1488630733126 Getting attrs for repeating sections for abilityChecks.updateMacro 1488630733232 Got attributes for repeating sections abilityChecks.updateMacro 1488630733232 Processing start for repeating sections abilityChecks.updateMacro 1488630733234 Processing end for repeating sections abilityChecks.updateMacro 1488630733234 Setting attrs for abilityChecks.updateMacro 1488630733255 Set attributes for repeating sections abilityChecks.updateMacro Something is Very, Very, Wrong here. On the client, this process took 3.8 seconds. I live 1200m up the side of a mountain in Spain; I have WiMAX internet that relies on LOS to the top of the mountain on the other side of the valley. At the moment that signal is travelling through 8km of dense cloud, each way , before it even gets into a wired connection that ultimately has to go across the Atlantic and back. The API sheetworkers, on the other hand, which I presume are operating on a machine in the same building as the rest of the system, with nice big fat backbones between them, clock in at 12.5 seconds for exactly the same sequence.&nbsp; I'd venture to suggest that this is pretty conclusive evidence that the API sheetworker implementation has a significant performance bug in it somewhere!

Superb, thanks for the clarification Riley. It makes a lot more sense now that I understand more about the architecture of it. I also take your point about the processing load on the API server vs the client. I'd love to run as much as possible in the client;&nbsp; the problem we have is that we just don't have the same flexibility over what we can do on the client as we do under the API right now. I guess if you guys are concerned about the potential impact of running stuff on the API server it might be worth considering in the longer term how you can safely expand the extension options on the client. Obviously I understand that brings a whole load of new concerns with it though. As concerns this particular case, this is literally just a new sheet configuring itself. There really shouldn't be anything particularly heavy. As I said, the sheetworker processing itself happens in 1-3ms each time - it's really quick. The gets and sets aren't doing *that* much either - building the list of skills in a repeating section, setting up the default attribute values and modifiers. I can't imagine it's much more than 100 attributes in total. Furthermore, basically all of the setAttrs in the sheet are now {silent: true} so there should be almost no triggering to do after the initial attribute is set. I agree that the priority needs to be making the callback reliable; the performance is something that can be looked at (by both sides!) over time. I think you probably are still a member of the game that I'm using, but I will PM you a link and some more details again.

Riley D. said: Okay so I actually think I figured out what was going on. When there were no examples of an indexed key (in this case, nothing of type: "graphic" existed, when a lot of your calls were to find all graphics), rather than the new caching system correctly understanding to return an empty array, it was falling back to the old behavior of having to look through every single object in the entire API sandbox. I think this should now be fixed, and your example on the API Server on Dev seems about 1000% faster, haha. It's unlikely this actually would have happened in a real game since most real games would have at least one token or map on the tabletop, but I'm glad we caught it all the same. So let me know if that seems fixed to you and if so I'll move that + the previous set of fixes to Main. I also upgraded the NodeJS version to the 7.x series from the 6.x series. I looked and I don't think there any breaking changes that would affect anything (since they are mostly for things like the 'fs' module and other stuff you guys don't have access to anyway) but just in case I may leave this on Dev for a few days. Cool, thanks Riley. I've checked this with my test game, and it does indeed fix the problem there. However, the reason for me testing it was that there were other users who were seeing the behaviour, and their campaigns weren't unrealistic in that way. I'm arranging with one of them to put his game on dev and install a sheet with extra logging and I will see if we can see any problems in that case still. Is there any way that this could be made fundamentally deterministic? As you yourself pointed out, fixing performance problems is all very well, but really the priority needs to be ensuring that the callback happens when it's supposed to. At some point, somewhere, there's going to be a big campaign in use when the API server is having a bad day, and we'll creep back over the timeout limit again even with everything working the way it ought to... and then anything that's relying on the ordering implied by the callback is going to break again... Thanks for the update to node 7.x! Will be good to be able to use String.startsWith() :-)