Zugg Software :: View topic - Verifying timing of settings being populated and compiled

Apprentice Joined: 03 Nov 2007 Posts: 132

In my debugger window, the first time I run a script after opening up cmud it will give me a lot of the following:

0.0016 | k CleanLus | [4] Func "sortWounds" changed from "" to "$tempwounds = 0;#LOOPDB @BodyList {#ADD $tempwounds %exec(%concat("@",%key))};CurrentWounds=$tempwounds
0.0001 | #CALL @sortStance()"
0.0008 | l CleanLus | Func "sortWounds" compiled (Normal) : $tempwounds = 0;#LOOPDB @BodyList {#ADD $tempwounds %exec...
0.0002 | k CleanLus | [4] Var "BodyList" changed from "" to "rleg|gut|larm|lleg|chest|head|rarm"
0.0026 | k CleanLus | [4] Var "CurrentWounds" changed from "0" to "5000"
0.0006 | k CleanLus | [4] Func "sortStance" changed from "" to "#say sortstance called
0.0001 | l CleanLus | Func "sortStance" compiled (Normal) : #say sortstance called

etc. etc. for every setting that is being called by the script. Depending on the script, this can actually be a pretty lengthy process as their might be a ton of settings that are being called for the first time that are being populated and compiled. Though it's usually seamless, sometimes as it gets more complicated and several threads are setting and compiling things at once I get some hiccups like this:

0.0001 | k CleanLus | [4] Trigger "StanceExpression" changed from "" to "#T- StanceExpression
0.0001 | #IF (!%trigger(StanceAlarm)) {#T+ StanceAlarm}
0.0000 | #NOOP %alarm(StanceAlarm,1)"
0.0004 | l CleanLus | Trigger "StanceExpression" compiled (Normal) : #T- StanceExpression #IF (!%trigger(StanceAlarm)) {#T+ St...
0.0002 | c CleanLus | [6] ExpTrig : start : Expression "StanceExpression" : #T- StanceExpression #IF ...
0.0015 | l CleanLus | Trigger "StanceAlarm" compiled (Pattern) : *0.7
0.0007 | d CleanLus | [6] ExpTrig : stopped
0.0059 | k CleanLus | Trigger "StanceAlarm" changed from "" to "#IF (@StancePart != @Stancing) {goStance} {#T+ StanceExpression;#T- StanceAlarm}"
0.0006 | l CleanLus | Trigger "StanceAlarm" compiled (Normal) : #IF (@StancePart != @Stancing) {goStance} {#T+ StanceExpr...
0.0001 | k CleanLus | Trigger "StanceAlarm" changed from "" to "#IF (@StancePart != @Stancing) {goStance} {#T+ StanceExpression;#T- StanceAlarm}"
0.0005 | l CleanLus | Trigger "StanceAlarm" compiled (Normal) : #IF (@StancePart != @Stancing) {goStance} {#T+ StanceExpr...

(note the bolded part of the same alarm being called and compiled twice though it could only have been called once by the expression trigger )

CMUD threw an access violation error at me at this point. It only does this once and after that all scripts are called and run smoothly without being compiled again.

Is this how it's supposed to be working? And is there anyway to force all your settings to compile ahead of time so you aren't running into a situation where you all of a sudden are setting/compiling/and executing a whole slew of somewhat complicated settings all at the same time?

Posted: Tue Nov 20, 2007 8:05 pm

Is this happening when you load your settings, or when you actually run your script? Can you be more specific about how you are running your script and exactly when you are opening the debug window?

The Compiled messages are normal. CMUD only compiles the first time you use a setting. This is done to spread out the compile time so that it doesn't really have any impact. As you can see from the above timings, the compiling is very fast most of the time. If you *really* wanted to force everything to compile, you can run the Compatibility Report in the settings editor. That loops through all settings and compiles them.

However, I don't really understand all of the messages about 'something changed from "" to "whatever script"'. That seems odd. So that's why I'd like to see more of a step-by-step procedure on how you are getting this.

Apprentice Joined: 03 Nov 2007 Posts: 132

Step 1: Launch CMUD
Step 2: Click on the session I want to open
Step 3: Click on Open Session Offline
Step 4: Open the Debugger window
Step 5: Connect to the MUD
Step 6: Watch a whole slew of triggers start compiling in the debugger (which is kind of odd I suppose)
Step 6: Do something to cause one of my scripts to fire
Step 7: Watch the scripts load up and compile in the debugger window as shown in the examples above

Now my setup in this situation is that I have a package that has all my settings contained in it. The only settings in the session window are the autolog. I don't load the package again when I open up the session. It only does it the first time the setting is called and then things work pretty smoothly.

My debugger has always been showing this. I thought it was normal but figured I'd ask since I get the weird quirks sometimes.

EDIT: I just ran the compatibility report to see if I got something different but I basically get:

| k Lusterni | Alias "prompton" changed from "" to "PromptFire=1"
0.0007 | l Lusterni | Alias "prompton" compiled (Normal) : PromptFire=1
0.0005 | k Lusterni | Alias "promptoff" changed from "" to "PromptFire=0"
0.0005 | l Lusterni | Alias "promptoff" compiled (Normal) : PromptFire=0
0.0007 | k Lusterni | Alias "setmana" changed from "" to "#IF (@callVariable(PromptFire)) {#PROMPT DesiredManaPercent "Enter Standard Mana Elixir Percentage";#PROMPT SparkleManaPercent "Enter Sparkleberry Mana Percentage";#PROMPT ScrollManaPercent "Enter Scroll Mana Percentage";#PROMPT MinimumManaPercent "Enter Priority Mana Elixir Percentage"} {DesiredManaPercent=%1;SparkleManaPercent=%2;ScrollManaPercent=%3;MinimumManaPercent=%4};showmana"
0.0018 | l Lusterni | Alias "setmana" compiled (Normal) : #IF (@callVariable(PromptFire)) {#PROMPT DesiredManaPerce...

For all my settings.

Apprentice Joined: 03 Nov 2007 Posts: 132

This is even happening as the norm for my test sessions:

0.0074 | c testsess | [1] testsession Comline : start : #VAR TestVar 1
0.0091 | k testsess | [1] Var "TestVar" changed from "0" to "1"
0.0201 | f testsess | Expression: @TestVar
0.0132 | k testsess | [1] Trigger "TestExpression" changed from "" to "#T- TestExpression;#T+ TestAlarm"
0.0185 | l testsess | Trigger "TestExpression" compiled (Normal) : #T- TestExpression;#T+ TestAlarm
0.0098 | c testsess | [2] ExpTrig : start : Expression "TestExpression" : #T- TestExpression;#T+ Test...
0.0089 | l testsess | Trigger "TestAlarm" compiled (Pattern) : *1
0.0104 | d testsess | [2] ExpTrig : stopped
0.0060 | d testsess | [1] testsession Comline : stopped
0.0105 | d testsess | [2] ExpTrig : terminated
0.9967 | k testsess |Trigger "TestAlarm" changed from "" to "#IF (@TestVar) {#say Test Alarm Firing} {#T- TestAlarm;#T+ TestExpression}"
0.0080 | f testsess |Alarm: *1
0.0056 | l testsess |Trigger "TestAlarm" compiled (Normal) : #IF (@TestVar) {#say Test Alarm Firing} {#T- TestAlarm;#T...
0.0098 | c testsess |[3] testsession Trigger : start : Alarm "TestAlarm" : #IF (@TestVar) {#say Test Alarm Firin...
0.0084 | a testsess |6900h, 6000m, 5700e, 9p, 32400en, 27900w elrx<>-Test Alarm Firing

Enchanter Joined: 09 Sep 2007 Posts: 605

Posted: Tue Nov 20, 2007 10:12 pm

Yes, in general. This kind of message really shouldn't happen. And it is *supposed* to truncate the script length, which seems to be another problem.

But if you can find a case where this is happening, let me know exactly how to reproduce it.

So, please show me the *exact* steps to reproduce this. I tried this and didn't get any message like that:

1) Run CMUD and press ESC to close session window
2) Select Window/Script debugger. Verify that the "Show compiled" and "Show var changes" messages are enabled.
3) Type

#TRIGGER (@TestVar) {#T- TestExpression;#T+ TestAlarm}
#VAR TestVar 1

it displayed:

Apprentice Joined: 03 Nov 2007 Posts: 132

I have trouble giving any more exact instructions then what I gave as that is *exactly* what I do and it's all that I do. I'm really not doing anything special, just running the program....

For my test session this is what I do. The key is that the settings are already pre-existing. I am not creating them at the same time that this is happening. They already exist. When I do the steps you did above I get the same results you did. Let's try something else.

1. Launch CMUD
2. Click the "New Session" button
3. Type "testsettings" in the Session title.
4. Leave the Host and Port blank
5. Click on "Open Session Offline"
6. Type: #TRIGGER (@TestVar) {#say Test Expression firing}
7. Type #VAR TestVar 0
8. Select File/Exit
9. Launch CMUD
10. Select the "testsettings" window
11. Click on "Open session offline"
12. Select Window/Script Debugger
13. Ensure that the "Messages" drop-down menu has everything except "Show Ansi Codes" and "Show raw session input/output" selected
14. Type: #VAR TestVar 1 on the command line

You should get the following debugger results:

0.0009 | c testsett | [1] testsettings Comline : start : #VAR TestVar 1
0.0027 | k testsett | [1] Var "TestVar" changed from "0" to "1"
0.0010 | f testsett | Expression: @TestVar
0.0014 | k testsett | [1] Trigger "@TestVar" changed from "" to "#say Test Expression firing"
0.0010 | l testsett | Trigger "@TestVar" compiled (Normal) : #say Test Expression firing
0.0008 | c testsett | [2] ExpTrig : start : Expression "@TestVar" : #say Test Expression firing
0.0014 | a testsett |Test Expression firing
0.0016 | d testsett | [2] ExpTrig : stopped
0.0012 | d testsett | [1] testsettings Comline : stopped
0.0036 | d testsett | [2] ExpTrig : terminated

Is that what you're looking for?

Enchanter Joined: 09 Sep 2007 Posts: 605

Never know is it a bug or a feature since debugger been introduced. Smile

Ok, it is a bug. And since it is a bug, I'll look more closely at it.

Can't help you with a procedure, since I get random results on several CMUD runs. Hope Malach or others will find a key.

Right now I can only say that sometimes CMUD consider a setting of any type (variable, alias, trigger) as having its type=variable (i.e. debugger message starts witk "k" letter), and therefore it shows all the script body.

Apprentice Joined: 03 Nov 2007 Posts: 132

Further testing. This is an add on to the above test steps:

15. Type: #ALIAS test {#say TestAlias}
16. Type: #TRIGGER {TestPattern} {#say Test firing}
17. Type: #FUNCTION TestFunction {#say TestFunction called}
18. Exit out of CMUD
19. Launch CMUD
20. Click on "testsettings" window
21. Click on "Open session offline"
22. Open the debugger window
23. Type: #say TestPattern
24. Type: test
25. Type: #CALL @TestFunction()

You should get the following results:

0.0008 | c testsett | [2] testsettings Comline : start : #say TestPattern
0.0021 | a testsett |TestPattern
0.0007 | k testsett | Trigger "TestPattern" changed from "" to "#say Test firing"
0.0009 | f testsett | Pattern: TestPattern
0.0009 | l testsett | Trigger "TestPattern" compiled (Normal) : #say Test firing
0.0008 | c testsett | [3] testsettings Trigger : start : Pattern "TestPattern" : #say Test firing
0.0013 | a testsett |Test firing
0.0011 | d testsett | [3] testsettings Trigger : stopped
0.0013 | d testsett | [2] testsettings Comline : stopped
3.8749 | ---
0.0008 | c testsett | [2] testsettings Comline : start : test
0.0016 | k testsett | [2] Alias "test" changed from "" to "#say TestAlias"
0.0010 | l testsett | Alias "test" compiled (Normal) : #say TestAlias
0.0008 | a testsett |TestAlias
0.0014 | d testsett | [2] testsettings Comline : stopped
5.2611 | ---
0.0008 | c testsett | [2] testsettings Comline : start : #CALL @TestFunction()
0.0017 | k testsett | [2] Func "TestFunction" changed from "" to "#say TestFunction called"
0.0008 | l testsett | Func "TestFunction" compiled (Normal) : #say TestFunction called
0.0009 | a testsett |TestFunction called
0.0014 | d testsett | [2] testsettings Comline : stopped

I did this to just show it's happening with all types of settings and looks the same regardless of the setting type. I also notice it's the "k" line which is used to show variable changes. No idea what that means but it's consistent.

Posted: Tue Nov 20, 2007 11:05 pm

OK, that's good. Now I can reproduce the problem. That's exactly the kind of step-by-step procedure that I needed. As you said, the key is that you need to open an existing session and not just use the blank session. In your original procedure you had:

Step 5: Connect to the MUD
Step 6: Watch a whole slew of triggers start compiling in the debugger (which is kind of odd I suppose)
Step 6: Do something to cause one of my scripts to fire

and obviously those are steps that I cannot follow on my system here because I don't have your MUD settings.

Anyway, I've reproduced the bug and should be able to fix it now.

Oh yeah, the debugger message says "Show variable changes", but it really shows any change to *any* setting, not just variables. Normally this isn't an issue because you shouldn't see anything change except variables. But it's also useful if you are changing an alias or something somewhere else. So the fact that it shows any setting change is normal. It just shouldn't be showing the initial "changed from "" to whatever" stuff, so that's the weird part.

Posted: Tue Nov 20, 2007 11:09 pm

Ah ha! I found it. CMUD caches the "value" of each setting internally. For a setting like a trigger, the "value" is the script itself. This cache is only updated as needed. So, for example, if you never execute a particular trigger, it's script is never loaded from the internal database. So, the first time you access a setting, it gets loaded into the cache from the internal database.

The "Show variable changes" message is hooked into the "SetValue" method for settings. So when a trigger is first loaded into the cache, it calls SetValue and you get the "changed from "" to whatever" message.

So, this is actually perfectly normal. It's just a bit annoying to see it in the output window, so I'll try to block that initial call.

It only shows up when loading a session because when you create a trigger from the command line, it already loads the internal cache. So it's only when loading a database that the cache comes into operation, like when you load a session.

Anyway, the bottom line is that you don't need to worry about this. I'll filter the debugger so these messages are not shown, but it doesn't indicate any problems with your scripts.

SubAdmin Joined: 18 Nov 2001 Posts: 5182

There is one thing I see your previous post Zugg

Posted: Wed Nov 21, 2007 1:12 am

Yep, I noticed that too, but haven't been able to track down the cause. I haven't seen it happen with anything except expression triggers and only when they are first created. It's possible that this happened in my example because the expression trigger was created before the @TestVar variable was created. This means that the expression trigger had what I call a "weak reference" to a variable name (but it couldn't resolve the actual reference). So creating the @TestVar variable might have caused it to compile again to replace the weak reference with a normal compiled reference. Not sure though.

Apprentice Joined: 03 Nov 2007 Posts: 132

My first example showed an alarm being compiled twice. Here are the lines again:

0.0059 | k CleanLus | Trigger "StanceAlarm" changed from "" to "#IF (@StancePart != @Stancing) {goStance} {#T+ StanceExpression;#T- StanceAlarm}"
0.0006 | l CleanLus | Trigger "StanceAlarm" compiled (Normal) : #IF (@StancePart != @Stancing) {goStance} {#T+ StanceExpr...
0.0001 | k CleanLus | Trigger "StanceAlarm" changed from "" to "#IF (@StancePart != @Stancing) {goStance} {#T+ StanceExpression;#T- StanceAlarm}"
0.0005 | l CleanLus | Trigger "StanceAlarm" compiled (Normal) : #IF (@StancePart != @Stancing) {goStance} {#T+ StanceExpr...

In this example all of the variables that the alarm referenced in the body were already created. This was also about the time I got an access violation error. Also the alarms were already in existence and were just being enabled in this example.

SubAdmin Joined: 18 Nov 2001 Posts: 5182

Right, and we can't replicate that one. I would love to find a good procedure for Zugg, but so far have been unsuccessful.