Register to post in forums, or Log in to your existing account
 

Play RetroMUD
Post new topic  Reply to topic     Home » Forums » CMUD Beta Forum
charneus
Wizard


Joined: 19 Jun 2005
Posts: 1876
Location: California

PostPosted: Sat Jul 18, 2009 12:15 am   

[3.09]CMUD hangs trying to load package [Solved]
 
I attempted to use my existing session after downloading 3.09. CMUD hung and I had to CTRL+ALT+DEL to get it to close. I opened up a new session and attempted to open the package that way. CMUD still hung. I don't know what the problem is, because I'm able to use 3.08 without any problems at all. If you need me to, I can send the package to you.

Charneus


Last edited by charneus on Sat Jul 18, 2009 12:32 am; edited 1 time in total
Reply with quote
charneus
Wizard


Joined: 19 Jun 2005
Posts: 1876
Location: California

PostPosted: Sat Jul 18, 2009 12:24 am   
 
Heh. Upon looking at the version history, I wonder if it has anything to do with the conversion... *sigh*
Reply with quote
Zugg
MASTER


Joined: 25 Sep 2000
Posts: 23377
Location: Colorado, USA

PostPosted: Sat Jul 18, 2009 12:25 am   
 
You might need to be patient if it's a big package. v3.09 converts packages into SQLite v3 and doesn't give any progress bar because I thought it was fast. So try waiting a few minutes. If it still doesn't complete, definitely send me the package.
Reply with quote
charneus
Wizard


Joined: 19 Jun 2005
Posts: 1876
Location: California

PostPosted: Sat Jul 18, 2009 12:33 am   
 
Yeah, that's what it was. Took about 5 minutes to convert it, I suppose. But then again I'm dealing with...

Triggers: 463 Aliases: 247 Variables: 314 Paths: 0 Macros: 40 Class Folders: 165 Mapped Zones: 255 Menus: 3 Tabwords: 0 Status Windows: 2 Directions: 16

Some of those variables are pretty big, too. Sorry for any alarm! :P

Charneus
Reply with quote
ReedN
Wizard


Joined: 04 Jan 2006
Posts: 1279
Location: Portland, Oregon

PostPosted: Sat Jul 18, 2009 12:39 am   
 
I was just about to post about this 'bug' as well (and that was even with knowing about the conversion). Cmud is listed in the task manager as 'Not Responding' and it is only using about 5% of the CPU, so it didn't look like it was doing something, it looked like it was locked-up.

Edit: It's also freaky that the new pkg file is 1/3 the size of the old file. Was the old file inefficient or did I just lose 1/3 of my settings?
Reply with quote
Zugg
MASTER


Joined: 25 Sep 2000
Posts: 23377
Location: Colorado, USA

PostPosted: Sat Jul 18, 2009 12:55 am   
 
Still send me your package file. I can use it for testing and implement a conversion progress bar. I guess my packages are all pretty small since I've waited at most 5 seconds for the conversions here (or maybe it's a faster computer).

It's probably not a CPU intensive operation though (like what ReedN said). I think SQLite is probably doing more file I/O than actual CPU work to do the database conversion.

Not sure about the new size. If you are missing anything in your package, send me the original so I can try converting it here. It's possible the old file was more inefficient since SQLite 2.8 is pretty old. But I don't know enough of it's internal details to answer.
Reply with quote
ReedN
Wizard


Joined: 04 Jan 2006
Posts: 1279
Location: Portland, Oregon

PostPosted: Sat Jul 18, 2009 1:00 am   
 
I sent you the package. Let me know if it doesn't arrive, we had a hard time getting it through your filter last time.
Reply with quote
wrym
Magician


Joined: 06 Jul 2007
Posts: 349
Location: The big palace, My own lil world

PostPosted: Sat Jul 18, 2009 1:22 am   
 
I have a couple decent sized packages myself, took me a few minutes to convert them. While it was converting I checked the reliability and performance monitoring (windows vista) and it didn't look like cmud was using a lot of I/O bandwidth either, a pretty even 81xx B/min write, 0 read while i was checking
_________________
"To the engineer, all matter in the universe can be placed into one of two categories: (1) things that need to be fixed, and (2) things that will need to be fixed after you've had a few minutes to play with them" - Scott Adams, The Dilbert Principle
Reply with quote
charneus
Wizard


Joined: 19 Jun 2005
Posts: 1876
Location: California

PostPosted: Sat Jul 18, 2009 1:35 am   
 
Sent my package as well. :P

Charneus
Reply with quote
Zugg
MASTER


Joined: 25 Sep 2000
Posts: 23377
Location: Colorado, USA

PostPosted: Sat Jul 18, 2009 1:35 am   
 
I received ReedN's package file, thanks.

I've never found a good way to really monitor I/O performance, even with the Vista performance monitor. I've seen Windows File Explorer sit there and take minutes to load a directory listing, and the file I/O (nor the CPU) never shows anything doing much. I think the problem is that Windows hides a bunch of system performance issues from us. So if it's something internal to Windows, or a driver or something, then it doesn't show up in the performance monitor.

But who knows. I'm no expert on the internal workings of SQLite. All CMUD is doing is reading records from the old database and then writing them to the new database. Then it renames the files so the new v3 database has the same name as the old database.
Reply with quote
Vijilante
SubAdmin


Joined: 18 Nov 2001
Posts: 5182

PostPosted: Sat Jul 18, 2009 1:46 am   
 
I am not really sure what the interface between your code and the sqlite3.dll is doing but I am going to guess it follows the description for preforming an SQL statement here.
http://sqlite.org/c3ref/stmt.html

Based on wyrm's numbers: I am also guessing that the 2.8 database is fully loaded into memory; and that the "prepare" portion of the database write is what is taking so long. If the interface you are using doesn't have API portions to retain and reuse prepared SQL statements, then I would suggest deriving a new class to add them.

Also looking at http://sqlite.org/c3ref/config.html you might be able to make it faster by disabling the threadsafe during the operation. Doing this would probably not make a major impact on preformance, but since this is an exclusive operation it might be good. Again the interface between you and the dll might get in the way.
_________________
The only good questions are the ones we have never answered before.
Search the Forums
Reply with quote
Vijilante
SubAdmin


Joined: 18 Nov 2001
Posts: 5182

PostPosted: Sat Jul 18, 2009 2:22 am   
 
Zugg wrote:
I've never found a good way to really monitor I/O performance, even with the Vista performance monitor. I've seen Windows File Explorer sit there and take minutes to load a directory listing, and the file I/O (nor the CPU) never shows anything doing much. I think the problem is that Windows hides a bunch of system performance issues from us. So if it's something internal to Windows, or a driver or something, then it doesn't show up in the performance monitor.
Google "sysinternals". I have used thier filemon and regmon tools for over a decade. They have since been bought by MS, but the quality and ease of use of the tools has not been degraded.
_________________
The only good questions are the ones we have never answered before.
Search the Forums
Reply with quote
Vijilante
SubAdmin


Joined: 18 Nov 2001
Posts: 5182

PostPosted: Sun Jul 19, 2009 12:47 am   
 
When the conversion for the mudlist had already taken 30 seconds and barely showed any progress on the bar I decided to look into the I/O operations.

It looks like a number of record are held and written in a batch. There appear to be 3 write phases involved with each batch, and a consitent per batch time frame of 300ms. Based on the 0% processor usage during the operation I would say it was waiting on a mutex between phases. The consistency of the time increments makes me think that it is doing a Synchronize with the main thread prior to preforming each phase of the writes.

I am going to guess that either the dll was not compiled with the thread safe capabilities, or that the interface you are using isn't properly determining the thread safe ability. If either of those is true it will affect performance in other places.
_________________
The only good questions are the ones we have never answered before.
Search the Forums
Reply with quote
Anaristos
Sorcerer


Joined: 17 Jul 2007
Posts: 821
Location: California

PostPosted: Sun Jul 19, 2009 2:58 am   
 
I suspect that the problem is with the database LOCK. In an ideal batch operation, the LOCK should only be acquired once and released when all the INSERTs or UPDATEs are done. My old package size was 1897K. It took 12 minutes to convert into 810K SQLite3 file.
_________________
Sic itur ad astra.
Reply with quote
Vijilante
SubAdmin


Joined: 18 Nov 2001
Posts: 5182

PostPosted: Sun Jul 19, 2009 6:25 am   
 
I have done some more testing and reading on this. The timing pieces I was looking at before are just the way NTFS does its file caching and physical write operations. That eliminates all thoughts about threading inefficiencies. I also tested a 3.5.1 dll build I had, and got nearly identical results. That should rule out build specific as well.

There is a fair bit of inefficiency from the class that interfaces your SQL to the dll's API, but most of the speed hit seems to be from trying to be very safe with the data. In this case data safety is not required if the files can be renamed and kept.

After reading quite a bit more at sqlite.org I think I found a workable solution. Adding a few PRAGMA statements at the start of the migration will make a huge difference. http://sqlite.org/pragma.html

PRAGMA journal_mode = OFF; PRAGMA synchronous=0;

I tested adding that line to the complete set of CREATE's for an empty map database and it cut the time from 15 seconds to 200ms. You will have to reset them to safe values after the database has been migrated.
_________________
The only good questions are the ones we have never answered before.
Search the Forums
Reply with quote
Anaristos
Sorcerer


Joined: 17 Jul 2007
Posts: 821
Location: California

PostPosted: Sun Jul 19, 2009 7:46 am   
 
The only thing that bothers me about your idea, Vijilante, is that I have a 27000+ record map database. That means that when it was converted to SQLite3, 27000+ records had to be read from the Access file and then added to the new database. The conversion of the map file took only a fraction of the time the package conversion did and the package file is very small in comparison.
_________________
Sic itur ad astra.
Reply with quote
Zugg
MASTER


Joined: 25 Sep 2000
Posts: 23377
Location: Colorado, USA

PostPosted: Sun Jul 19, 2009 5:26 pm   
 
Yep, the "synchronous=0" flag is what I need. I was looking at the code and in the code that converts the old map databases from ADO/MDAC to SQLite v3 I have that. But the code that converts the SQLite v2 to v3 doesn't have that. I remember having similar speed issues when CMUD v3 first came out and was converting maps. So I just need to steal some of that code for the package conversion. Should be pretty easy to handle. Sorry I missed this, but I'll release another version later next week with the improved conversion speed and a progress bar.
Reply with quote
Vijilante
SubAdmin


Joined: 18 Nov 2001
Posts: 5182

PostPosted: Sun Jul 19, 2009 5:28 pm   
 
Instead of being bothered you should examine the behavior and understand what is going on. I did a conversion on a 24Mb mdb, and it took just under 9 minutes. An example of the I/O activity from the middle of the log is
Code:
12:34:25.596 PM   cMUD.exe:7748   WRITE   C:\CMUD302\fullachaeanmap.dbm   SUCCESS   Offset: 0 Length: 8192   
12:34:25.596 PM   cMUD.exe:7748   WRITE   C:\CMUD302\fullachaeanmap.dbm   SUCCESS   Offset: 57344 Length: 8192   
12:34:25.596 PM   cMUD.exe:7748   WRITE   C:\CMUD302\fullachaeanmap.dbm   SUCCESS   Offset: 2228224 Length: 8192   
12:34:25.596 PM   cMUD.exe:7748   WRITE   C:\CMUD302\fullachaeanmap.dbm   SUCCESS   Offset: 2236416 Length: 8192   
12:34:25.596 PM   cMUD.exe:7748   WRITE   C:\CMUD302\fullachaeanmap.dbm   SUCCESS   Offset: 2244608 Length: 8192   
12:34:25.596 PM   cMUD.exe:7748   WRITE   C:\CMUD302\fullachaeanmap.dbm   SUCCESS   Offset: 2252800 Length: 8192   
12:34:25.596 PM   cMUD.exe:7748   WRITE   C:\CMUD302\fullachaeanmap.dbm   SUCCESS   Offset: 2260992 Length: 8192   
12:34:25.596 PM   cMUD.exe:7748   FLUSH   C:\CMUD302\fullachaeanmap.dbm   SUCCESS      
12:34:25.596 PM   cMUD.exe:7748   WRITE    C:\$ConvertToNonresident   SUCCESS   Offset: 0 Length: 8192   
12:34:25.606 PM   cMUD.exe:7748   WRITE    C:\$ConvertToNonresident   SUCCESS   Offset: 57344 Length: 8192   
12:34:25.606 PM   cMUD.exe:7748   WRITE    C:\$ConvertToNonresident   SUCCESS   Offset: 2228224 Length: 40960   
12:34:25.687 PM   cMUD.exe:7748   CLOSE   C:\CMUD302\fullachaeanmap.dbm-journal   SUCCESS
The first 2 WRITE's are control records. The next 5 are data records. Then the FLUSH causes the caching to commit to the disk with a physical write. Note the 80ms that occurs after the final commit. The overhead time is consitently on the physical writes because that is what is requested with the default synchronous pragma. If I ran the disk monitor at the same time I would see that the delay is Windows waiting to make sure the drive has completed writing.

This log is also telling me is that Zugg is doing 5 INSERT's with each transaction. The lowest time for the "safe" physical write I have seen is 40ms.

Now from a package conversion, with a final size of 49Kb and total time of 45 seconds.
Code:
1:13:30.518 PM   cMUD.exe:7748   WRITE   C:\CMUD302\Packages\achaea_def.db3   SUCCESS   Offset: 0 Length: 1024   
1:13:30.518 PM   cMUD.exe:7748   WRITE   C:\CMUD302\Packages\achaea_def.db3   SUCCESS   Offset: 47104 Length: 1024   
1:13:30.518 PM   cMUD.exe:7748   FLUSH   C:\CMUD302\Packages\achaea_def.db3   SUCCESS      
1:13:30.518 PM   cMUD.exe:7748   WRITE    C:\$ConvertToNonresident   SUCCESS   Offset: 0 Length: 4096   
1:13:30.518 PM   cMUD.exe:7748   WRITE    C:\$ConvertToNonresident   SUCCESS   Offset: 45056 Length: 4096   
1:13:30.588 PM   cMUD.exe:7748   CLOSE   C:\CMUD302\Packages\achaea_def.db3-journal   SUCCESS
Here we see a single INSERT per transaction. The overhead time is the same 80ms as the map conversion that used 5.

That leads to the conclusion that Zugg can either use BEGIN TRANSACTION and END TRANSACTION similar to how he does for the map conversion. If he used the same factor of 5 then the package conversions would end up nearly 5 times faster than they are now. Alternately he can eliminate the overhead entirely and make the conversion run 50 times faster. He could also apply the same pragma statements to the map conversion making that faster as well.

In fact the more I think about it, the more I think that PRAGMA synchronous=0 should be used all the time. The safety provided by the default synchronous setting is mostly to cover against a power failure in the middle of a write. If I understand things correctly the journal is also examined when the database is first opened to determine if the was an interrupted write. The journal plus the backups CMud is making provide more then enough data security.
_________________
The only good questions are the ones we have never answered before.
Search the Forums
Reply with quote
Anaristos
Sorcerer


Joined: 17 Jul 2007
Posts: 821
Location: California

PostPosted: Sun Jul 19, 2009 10:33 pm   
 
I can see your point. My point was that for a relative small file as the package file is, I would have batched all then INSERTs and just done one COMMIT at the end. True, I would lose all the data if something like a crash occurred, but for the size of the file, the danger is statistically small.
_________________
Sic itur ad astra.
Reply with quote
Zugg
MASTER


Joined: 25 Sep 2000
Posts: 23377
Location: Colorado, USA

PostPosted: Thu Jul 23, 2009 7:03 pm   
 
OK, I was able to fix the conversion speed problem. The 3.10 version will set "synchronous=0" and also put the statements within a transaction the way it was supposed to (more like how the map conversion is done). This change shows *significant* speed improvements when testing with the package file that ReedN sent me.

Also, I can confirm that database files in SQLite v3 are definitely much smaller than SQLite v2. ReedN's package that I was testing went from 2.84 MB to 920 KB. The MUD database goes from 3.38MB to 2.21MB. So they obviously made some changes in how the data was stored to make it more efficient. As far as I can tell, everything is being properly converted.

The 3.10 version also adds a progress bar so that if it's still slow for some reason, you'll see the progress.

The downside of these changes is that if the power goes off during the conversion, then the resulting SQLite v3 file might be corrupted. But since the file is only renamed back to the original package filename after success, this just means that the conversion will start over again the next time you run CMUD. So I don't see any real downside to this.
Reply with quote
Display posts from previous:   
Post new topic   Reply to topic     Home » Forums » CMUD Beta Forum All times are GMT
Page 1 of 1

 
Jump to:  
You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum
You cannot vote in polls in this forum

© 2009 Zugg Software. Hosted by Wolfpaw.net