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:
183 184 185 186 187 188 189 190 191 192 193 194 195 196 197
But check out these two:
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
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:
47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63
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:
...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.
177 178 179 180 181 182 183 184 185 186 187 188 189 190 191
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:
103 104 105 106 107 108 109 110
Incorrect results from restocking
Now for a little SQL tweaking.
208 209 210 211 212 213 214 215 216 217 218 219 220 221 222
Believing my comment, I dig into the SQL for the stored procedure.
2187 2188 2189 2190 2191 2192 2193 2194 2195 2196 2197 2198 2199 2200 2201
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.
316 317 318 319 320 321 322 323 324 325 326 327 328 329 330
It expects a data table back? The procedure certainly doesn’t return one. Could it be that simple?
316 317 318 319 320 321 322
65 scenarios (65 passed) 574 steps (574 passed) 16m27.988s