301 Days (redux)

Day 75 - 100x Speedup

by Joe Threeohone

In which we cure blindness, but more importantly make the blog faster.

Test Every Day

We did Beer the same way we did Ale, and no surprises there.

A Tale of Two Testcases

After Ale and Beer, I got to work on the Blindness_Cure character effect. The actual effect seems to work well enough, and this test passes:

features/player_effects.featurelink
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197

Scenario: Blindness Cure cures Blindness
    Given I use the "minimal" database
    And I add player and character "TestBlind01"
    And I give the character a "blind" effect of "1" for "999" turns
    And the server is started
    And I log on as "TestBlind01"
    And I enter the game
    And I saw a message "You are blind!"
    And I exit the game
    And I exit the chat
    And I log out
    When I give the character a "blindness_cure" effect of "1" for "1" turns
    And I log on as "TestBlind01"
    And I enter the game
    Then I did not see a message "You are blind!"

But check out these two:

features/player_effects.featurelink
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228

Scenario: Blindness Cure gives appropriate output on curing blindness while offline
    Given I use the "minimal" database
    And I add player and character "TestBlind01"
    And I give the character a "blind" effect of "1" for "999" turns
    And the server is started
    And I log on as "TestBlind01"
    And I enter the game
    And I saw a message "You are blind!"
    And I exit the game
    And I exit the chat
    And I log out
    When I give the character a "blindness_cure" effect of "1" for "1" turns
    And I log on as "TestBlind01"
    And I enter the game
    Then within "1" turns I see the message "Your blindness has been cured!"

Scenario: Blindness Cure gives appropriate output on curing blindness while online
    Given I use the "minimal" database
    And I add player and character "TestBlind01"
    And I give the character a "blind" effect of "1" for "999" turns
    And I put a blindness cure in the the character's left hand
    And the server is started
    And I log on as "TestBlind01"
    And I enter the game
    And I saw a message "You are blind!"
    When I open "bottle"
    And I drink "bottle"
    Then within "1" turns I see the message "Your blindness has been cured!"

Which one do you think passes, and which one fails?

If you said the one where I cure the character’s blindness while they’re offline (which could never actually happen) fails, you get a point. I believe it’s because the effect text is being written to the client before it’s ready, but that’s not the lesson here.

I’ve been too quick to just tweak something in the database, instead of making it happen in the game itself. True, this can make the tests faster and/or more repeatable in some cases, but it leads to very artificial results. I marked the first test case as a bug, but is it? We’re testing a scenario which cannot naturally occur.

When I decided to write the second test case, I was surprised at how easy it was. Grab the appropriate potion from the production database into the minimal one, add a few steps (mostly using code we already had), and viola!

Going forward, I’ll try to favor a natural in-world way to get to a test scenario instead of relying completely on database tweaking.

Improve the Blog Every Third Day

The 100x speedup

Recently while working on a post, rendering the blog became unusably slow, even with just the one post isolated. So I narrowed down what was taking all the time:

plugins/code_block.rblink
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63

module Jekyll

  class CodeBlock < Liquid::Block
    CaptionUrlTitle = /(\S[\S\s]*)\s+(https?:\/\/\S+|\/\S+)\s*(.+)?/i
    Caption = /(\S[\S\s]*)/
    def initialize(tag_name, markup, tokens)
      @title = nil
      @caption = nil
      @filetype = nil
      @highlight = true
      if markup =~ /\s*lang:(\S+)/i
        @filetype = $1
        markup = markup.sub(/\s*lang:(\S+)/i,'')
      end
      if markup =~ CaptionUrlTitle
        @file = $1
        @caption = "<figcaption><span>#{$1}</span><a href='#{$2}'>#{$3 || 'link'}</a></figcaption>"

Line 61, where the markup is matched against the CaptionUrlTitle, was always the current line being executed when I would get impatient and abort the build. Throwing a little debug around it shed some light:

Checking  features/player_effects.feature https://gitlab.com/LiBiPlJoe/seitan-spin/blob/master/features/player_effects.feature#L183  against (?i-mx:(\S[\S\s]*)\s+(https?:\/\/\S+|\/\S+)\s*(.+)?)...
...that took 0.001 seconds.
Checking  features/player_effects.feature https://gitlab.com/LiBiPlJoe/seitan-spin/blob/master/features/player_effects.feature#L201  against (?i-mx:(\S[\S\s]*)\s+(https?:\/\/\S+|\/\S+)\s*(.+)?)...
...that took 0.0 seconds.
Checking  Assets/Managers/NpcManager.cs <a href="https://gitlab.com/LiBiPlJoe/ste-reez-muvi/blob/de2a511228e36fc59020c48311acf6eff1364129/Assets/Managers/NpcManager.cs#L116">https://gitlab.com/LiBiPlJoe/ste-reez-muvi/blob/de2a511228e36fc59020c48311acf6eff1364129/Assets/Managers/NpcManager.cs#L116</a>  against (?i-mx:(\S[\S\s]*)\s+(https?:\/\/\S+|\/\S+)\s*(.+)?)...
...that took 2.321133 seconds.
Checking  Assets/DragonsSpine/DAL/DBNPC.cs <a href="https://gitlab.com/LiBiPlJoe/ste-reez-muvi/blob/de2a511228e36fc59020c48311acf6eff1364129/Assets/DragonsSpine/DAL/DBNPC.cs#L136">https://gitlab.com/LiBiPlJoe/ste-reez-muvi/blob/de2a511228e36fc59020c48311acf6eff1364129/Assets/DragonsSpine/DAL/DBNPC.cs#L136</a>  against (?i-mx:(\S[\S\s]*)\s+(https?:\/\/\S+|\/\S+)\s*(.+)?)...
...that took 19.158096 seconds.

Not only the text we expect, but also the already-processed text is being pushed through the plugin. And when it’s the already-processed text, not only does it not match the regex, but it takes a huge amount of time.

Regenerating the whole blog?

...done in 1093.42754 seconds.

Let’s try something simple like skipping the regex if we see there’s already a link in the markup:

plugins/code_block.rblink
61

if markup.index('<a href').nil? && markup =~ CaptionUrlTitle

...done in 9.050517 seconds.

Yes, Virginia, that is a 100x speedup.

Regular expressions are a powerful tool, but it doesn’t come for free. There’s always a worst-case string, and it may take some real time to churn through it. In this case it’s worth doing some filtering of the incoming text before it gets to the complex regex (just take care that the filtering is not just as expensive).

Fix a Bug in the Legacy Code Every Fifth Day

Illegal values for APP_PROTOCOL

First, a trivial fix.

features/config_file.featurelink
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191

# bug - There are two special values, 'normal' and 'old-kesmai' that should not be allowed.
@bug
Scenario: APP_PROTOCOL set to invalid value - normal
	Given I use the "minimal" database as-is
	And I set "APP_PROTOCOL" in the config file to "normal"
	When the server is started
	Then the log shows a fatal error "Invalid APP_PROTOCOL"

# bug - There are two special values, 'normal' and 'old-kesmai' that should not be allowed.
@bug
Scenario: APP_PROTOCOL set to invalid value - old-kesmai
	Given I use the "minimal" database as-is
	And I set "APP_PROTOCOL" in the config file to "old-kesmai"
	When the server is started
	Then the log shows a fatal error "Invalid APP_PROTOCOL"

Not a serious bug, to be sure, as long as the config file doesn’t use one of the two magic strings in the code as the value for APP_PROTOCOL. Easy to guard against, though:

DragonsSpine/DragonsSpineMain.cslink
103
104
105
106
107
108
109
110

#region Bad Config
// Don't let APP_PROTOCOL be set to either of the predefined protocol identifiers.
if (APP_PROTOCOL == "normal" || APP_PROTOCOL == "old-kesmai")
{
    Utils.Log("Invalid APP_PROTOCOL.", Utils.LogType.SystemFatalError);
    return -1;
}
#endregion

Incorrect results from restocking

Now for a little SQL tweaking.

features/config_file.featurelink
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222

# bug - Restocking stored procedure, [prApp_Stores_Restock], returns zero despite rows
#         having been changed.
@bug
Scenario: ClearStores True, RestockStores True causes stores to be restocked on server startup
    Given I use the "minimal" database
    And I add a vendor "TestVend01"
    And I give vendor "TestVend01" the following items:
      | itemID  | notes      | original | stocked | restock |
      | 30480   | Small Rock | false    | 1       | 0       |
      | 33020   | Red Berries| true     | 7       | 33      |
    And I set "ClearStores" in the config file to "True"
    And I set "RestockStores" in the config file to "True"
    When the server executable is started
    And I allow time for the server to complete startup
    And the log shows "1" items restocked in stores

Believing my comment, I dig into the SQL for the stored procedure.

EntireDB-minimal.sqllink
2187
2188
2189
2190
2191
2192
2193
2194
2195
2196
2197
2198
2199
2200
2201

/****** Object:  StoredProcedure [dbo].[prApp_Stores_Restock]      ******/
SET ANSI_NULLS ON
GO
SET QUOTED_IDENTIFIER ON
GO
----------------------------------------------------------------------------
-- Restock items in the Stores table
----------------------------------------------------------------------------
CREATE PROC [dbo].[prApp_Stores_Restock]

AS
UPDATE    Stores
SET              stocked = restock
WHERE     (original = 1) AND stocked <> restock
GO

Seems like it should work fine, and return the number of rows that were updated. But sure enough, the log shows I was getting 0.

I did a web search, and the whole internet screams “NOCOUNT!”. I must have NOCOUNT enabled, on the connection or in the procedure or somewhere, and that must be my problem.

Except adding a SET NOCOUNT OFF to the procedure had no effect. And when I run the procedure in SQL Server Management Studio, and look at the messages tab, I am getting a notification of how many rows were changed.

So I turn to the server code, initially to add some more debug output.

DragonsSpine/DAL/DBWorld.cslink
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330

internal static int restockStoreItems()
{
    try
    {
        SqlStoredProcedure sp = new SqlStoredProcedure("prApp_Stores_Restock", DataAccess.GetSQLConnection());
        DataTable dtRestockStores = sp.ExecuteDataTable();
        if (dtRestockStores == null) { return -1; }
        else { return sp.ExecuteNonQuery(); }
    }
    catch (Exception e)
    {
        Utils.LogException(e);
        return -1;
    }
}

It expects a data table back? The procedure certainly doesn’t return one. Could it be that simple?

DragonsSpine/DAL/DBWorld.cslink
316
317
318
319
320
321
322

internal static int restockStoreItems()
{
    try
    {
        SqlStoredProcedure sp = new SqlStoredProcedure("prApp_Stores_Restock", DataAccess.GetSQLConnection());
        return sp.ExecuteNonQuery();
    }

Yes.

65 scenarios (65 passed)
574 steps (574 passed)
16m27.988s

Useful Stuff

Day 75 code - tests

Day 75 code - server