Bug in mapper database interaction

Posted by Horath on Sun 16 Oct 2011 09:42 PM — 20 posts, 89,662 views.

Horath United Kingdom Sun 16 Oct 2011 09:42 PM #0

Hi all,
I've been playing with Nicks mapper.lua and one of the MUSHClient interface scripts (in this case the Materia_magic mapper found in this thread http://www.gammon.com.au/forum/bbshowpost.php?id=10667&page=1) converting and modifying it for use with Shadowdale Mud (play.sdmud.org 7777) and have come across a piece of rather bizzare behaviour and its one thats independent of any changes Iv made to either mapper.lua or the interface script, or even the MUD/MUSH the client is connected to.

After a lot of hunting I think I have figured out where the abberant behaviour is happening and was hopeing that someone could at least confirm that I am not going crazy! and if possible shed some light on what the problem may be.

Below is detailed the steps to reproduce the bug followed by where i think something is going wrong.

Horath United Kingdom Sun 16 Oct 2011 09:43 PM #1

I am using MUSHClient 4.77

The bug can be reproduced (at least on my machine) using the version of mapper.lua supplied with MUSHClient install.

Pluging in the Matteria_magic mapper script( as detailed in http://www.gammon.com.au/forum/bbshowpost.php?id=10667&page=1) into a new world file.

Adding the following alias' in to the Matteria_magic mapper script


<!-- Manual Tester for bizzare bug -->

<!-- This alias tests a non buggy uid -->
 <alias
   enabled="y"
   match="^mapper bugtest1$" regexp="y"
   send_to="12">
  <send>
    t=os.time()
    uid = "3DCDDC5E426E2916A9ACA0AEA"
    room = load_room_from_database (uid)
    print("Time taken to load bugged room", os.time()-t, "s")
  </send>
 </alias>

<!-- This alias tests a the buggy uid -->
 <alias
   enabled="y"
   match="^mapper bugtest2$" regexp="y"
   send_to="12">
  <send>
    t=os.time()
    uid = "2E515665758C87202B281C7FC"
    room = load_room_from_database (uid)
    print("Time taken to load bugged room", os.time()-t, "s")
  </send>
 </alias>

<!-- This alias adds the two above uids to the database -->
 <alias
   enabled="y"
   match="^mapper bugtest set$" regexp="y"
   send_to="12">
  <send>
    t=os.time()
    uid = "2E515665758C87202B281C7FC"
    content_of_room = {}
    closed_exits_str = ""
    exits_str = ""
    roomname = ""
    roomdesc = ""

        db:exec ("BEGIN TRANSACTION;") 
  
        save_room_to_database (uid, roomname, Trim (roomdesc))
        save_exits_to_database (uid, exits_str, closed_exits_str)
    
        db:exec ("COMMIT;")

    uid = "3DCDDC5E426E2916A9ACA0AEA"


        db:exec ("BEGIN TRANSACTION;") 
  
        save_room_to_database (uid, roomname, Trim (roomdesc))
        save_exits_to_database (uid, exits_str, closed_exits_str)
    
        db:exec ("COMMIT;")


    print("Time taken to save bugged room", os.time()-t, "s")

  </send>
 </alias>

(CAUTION if you test this on a mud you play and use one of Nicks SQLITE database mappers (such as the Materia magic mapper) please back it up before trying this next bit as it will add entries to the database)
As a precaution I created a new world login to a random mud so as to produce a completely clean and empty database file.

Connect to the random mud (dont even need to create a character or log in)

type
mapper bugtest set

(this add 2 entries to the database (the one thats causing me the problem and another thats picked from a random room thats not showing the problem) with only uids no other info. This should display time taken as 0s (as in less than a second))

type
mapper bugtest1

(this loads the room with a uid that shows no problem and gives time for load on my machine again at less than a second)

type
mapper bugtest2

(this loads the bugged room at uid = 2E515665758C87202B281C7FC)

The second bug test on my machine always takes 4 seconds (give or take) to load the room, this is indepenent of room name/description and whether there are exits or not.

After a lot of hunting the only way i can get rid of the 4 seconds is by commenting out the query for room exits performed by the MUSHClient script on loading the room

Horath United Kingdom Sun 16 Oct 2011 09:45 PM #2


function load_room_from_database (uid)

  local room
 
  assert (uid, "No UID supplied to load_room_from_database")
  
  -- if not in database, don't look again
  if room_not_in_database [uid] then
    return nil
  end -- no point looking
  
  for row in db:nrows(string.format ("SELECT * FROM rooms WHERE uid = %s", fixsql (uid))) do
     room = {
       name = row.name,
       area = row.area,
       description = row.description,
       shop = row.shop,
       train = row.train,
       notes = row.notes,
  
       exits = {} }
      
-->    for exitrow in db:nrows(string.format ("SELECT * FROM exits WHERE fromuid = %s", fixsql (uid))) do
-->       room.exits [exitrow.dir] = tostring (exitrow.touid)
-->    end -- for each exit
    
  end   -- finding room

  if room then
    rooms [uid] = room
    return room
  end -- if found
  
  room_not_in_database [uid] = true
  return nil
    
end -- load_room_from_database

If the three lines arrowed above are commented out then the room loads in less than a second but as you can imagine the mapper no longer works as it doesnt load room exits

If they are in it takes 4 seconds.

The uid that is causeing the problem is the uid produced by a room in Shadowdale Mud through my triggers. Because of modifications I now have three querys on different tables in this section where the room is loaded and each query adds 4 seconds to the time so this room is taking 12seconds to load, all of the other 200+ I have mapped so far take less than a second to load (even with the three querys) This behaviour happens even if Im several rooms away from the one affected, if I enter the zone with the room 12+ steps away the mapper loads the room for dispaly it and it takes 12 seconds.

I can think of ways around this but would hate to map more of the mud and have this pop up again and again in random places.

I hope someone out there has some experience with SQLITE that might help me as all I can think is that somehow the uid in question is doing something strange to the SQLITE engine.

Slowly going insane,

Horath

Nick Gammon Australia Forum Administrator Mon 17 Oct 2011 06:42 AM #3

*boggle*

Well I can reproduce that, which is good I suppose.

That's extremely strange.

My debugging displays show this:


got room after 0.00011817086488008
room = 2E515665758C87202B281C7FC
done exits after 2.4980748957023
Time taken to load bugged room 3 s

So it read the room in after 118 uS which is fine. And it didn't find an exit, so it didn't waste time reading them. But to find "no exit", when exits were empty, takes 2.498 seconds!

The database is locked, maybe and times out?

If I type this into sqlite3.exe:


 SELECT * FROM exits WHERE fromuid = '2E515665758C87202B281C7FC';

... there is no noticeable delay. So something very strange is going on indeed.

I'll try to get to the bottom of it.

Nick Gammon Australia Forum Administrator Mon 17 Oct 2011 07:56 AM #4

So far I tried reversing the order in which you add the rooms, in case room 1 was somehow special. However that didn't work. And in any case, after deleting the rooms and exits the new rooms became room id 3 and 4, and the problem persisted.

Nick Gammon Australia Forum Administrator Mon 17 Oct 2011 08:11 AM #5

Right, well some light at the end of the tunnel ...

This alias reproduces the problem:


<alias
   enabled="y"
   match="^mapper bugtest3$" regexp="y"
   send_to="12">
  <send>
   t=os.time()
  
   for exitrow in db:nrows("SELECT * FROM exits WHERE fromuid = '2E515665758C87202B281C7FC'") do
   end -- for each exit
  
   print("Time taken to load bugged exit", os.time()-t, "s")
   </send>
 </alias>

Now this rules out problems with loading an exit after loading a room. And since that room doesn't have any exits on the database, I concentrated on the room ID 2E515665758C87202B281C7FC.

Strangely, changing it by removing stuff from the end didn't have any effect. But *this* did:


2F515665758C87202B281C7FC

So what is happening?

Well somewhere something is interpreting the ID as a large number, ie.

2e515665758

It must be taking around 3 seconds to find 2 times 10 to the power 515665758.

But why is it doing that? And why doesn't the Sqlite3.exe program do the same? At least this narrows it down.

Nick Gammon Australia Forum Administrator Mon 17 Oct 2011 08:27 AM #6

If you type this into sqlite3.exe:


SELECT * FROM exits WHERE fromuid = '2E515665758';

That takes about 2 seconds to execute. Despite it being a quoted match string, and fromuid being a string type.

Nick Gammon Australia Forum Administrator Mon 17 Oct 2011 08:42 AM #7

As a work-around, try changing the code that calculates the room hash, from:


 -- generate a "room ID" by hashing the room name, description and exits
  uid = utils.tohex (utils.md5 (roomname .. roomdesc .. exits_str .. map_str))

to:


 -- generate a "room ID" by hashing the room name, description and exits
  uid = utils.tohex ("x" .. utils.md5 (roomname .. roomdesc .. exits_str .. map_str))

Of course this will invalidate the current rooms, but if it fixes the speed problems it should be worth it, until I can work out why this is a problem in the first place.

Twisol USA Mon 17 Oct 2011 09:43 AM #8

Relevant question on StackOverflow: http://stackoverflow.com/questions/5348935/string-column-in-android-sqlite-db-being-converted-to-exponential-value

Basically, I think you need to change the affinity for that column to TEXT.

Nick Gammon Australia Forum Administrator Mon 17 Oct 2011 09:47 AM #9

This reproduces it:


DROP TABLE IF EXISTS rooms;
 DROP TABLE IF EXISTS exits;

 CREATE TABLE IF NOT EXISTS rooms (
     roomid        INTEGER PRIMARY KEY AUTOINCREMENT,
     uid           TEXT NOT NULL  -- unique room ID
   );

 CREATE TABLE IF NOT EXISTS exits (
     exitid      INTEGER PRIMARY KEY AUTOINCREMENT,
     fromuid     STRING  NOT NULL -- exit from which room (in rooms table)
   );

 CREATE INDEX IF NOT EXISTS fromuid_index ON exits (fromuid);

 SELECT * FROM exits WHERE fromuid = '2E515665758C87202B281C7FC';

The column type is string.

Nick Gammon Australia Forum Administrator Mon 17 Oct 2011 09:50 AM #10

However it looks like you are right. Changing it to TEXT rather than STRING fixes it.

Nick Gammon Australia Forum Administrator Mon 17 Oct 2011 09:59 AM #11

Uploaded amended mapper, changes here:

https://github.com/nickgammon/plugins/commit/9c3ff98811dc8f92cdbf3b06a5c851acfa39a6b7#Materia_Magica_Mapper.xml

Thanks, Twisol!

Horath United Kingdom Mon 17 Oct 2011 01:22 PM #12

Thanks guys,

This has been driving me crazy over the last few days, just updated my mapper module to make uids Text rather than String and this has solved the problem.

I had wondered if it was something to do with the first few chars in the uid. However checking my database I found plenty starting 2E##### so was a bit stuck. Of course looking back now all the other uid starting like this were along the lines of 2E25F#### and calculating 2E25 doesnt take anywhere near as long as 2E515665758.

Anyway all sorted now :)

Just need to iron out the other creases in my shadowdale mapper now :P

Horath

Fiendish USA Global Moderator Mon 17 Oct 2011 05:56 PM #13

Odd bug, though I have to wonder why your mud is sending such enormous room ids. Surely there aren't actually 2.29354263 × 10^29 unique rooms.

Shadowfyr USA Mon 17 Oct 2011 06:12 PM #14

If I where to guess.. I would say that "string" and "text" are handled differently on the basis that some applications may *need* to store big numbers in strings, so it gets funneled through a conversion function some place (it might be treated as a sort of 'variant' type), where "text" really is literally, "as is, don't do anything else to it". But, that is just guessing. Good thing to know to watch out for.

Nick Gammon Australia Forum Administrator Mon 17 Oct 2011 08:32 PM #15

Fiendish said:

Odd bug, though I have to wonder why your mud is sending such enormous room ids. Surely there aren't actually 2.29354263 × 10^29 unique rooms.

It's not sending them, that's the problem.

For MUDs that don't have room numbers/IDs the mapper is a bit of a problem. I worked around it by using the room description/minimap as a unique identifier, and then hashed that to make it a workable size (10 characters of hash rather than a whole room name/description).

Nick Gammon Australia Forum Administrator Tue 18 Oct 2011 05:01 AM #16

As a follow-up, I posted this bug to the SQLite3 mailing list, and got a fix within a day:

http://www.sqlite.org/src/ci/59bb999c8b?sbs=0

I'll incorporate that into the next release of MUSHclient.

Fiendish USA Global Moderator Mon 24 Oct 2011 12:34 AM #17

Is it just me or does this make dbs with numeric room ids suddenly almost double in size? :\

Nick Gammon Australia Forum Administrator Mon 24 Oct 2011 02:20 AM #18

Really? Try running a vacuum or something.

Fiendish USA Global Moderator Tue 25 Oct 2011 05:29 AM #19

Ah. Fixed.