Day 75 - 100x Speedup · 301 Days (redux)

Table of Contents

No more than ten to twenty million killed, tops.

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

GitLab

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

GitLab

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

GitLab

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

GitLab

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

GitLab

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

GitLab

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

GitLab

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

GitLab

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

GitLab

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

GitLab

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
#

GDEX 2016 (formerly Ohio Gamedev Expo)

Day 75 code - tests

Day 75 code - server

Test Every Day #

A Tale of Two Testcases #

Improve the Blog Every Third Day #

The 100x speedup #

Fix a Bug in the Legacy Code Every Fifth Day #

Illegal values for APP_PROTOCOL #

Incorrect results from restocking #

Useful Stuff #

Test Every Day
#

A Tale of Two Testcases
#

Improve the Blog Every Third Day
#

The 100x speedup
#

Fix a Bug in the Legacy Code Every Fifth Day
#

Illegal values for APP_PROTOCOL
#

Incorrect results from restocking
#

Useful Stuff
#