MySQL has Gone Away - Threaded Loading

[John Adams]

Welp, I thought I could finally blame Scatman for a bug, but unfortunately it looks as though this one is back in Jabantiz's lap

Mind you, this is another "all of a sudden"... only started happening to me recently.

Tonight, while using Threaded Loading, my world "all of a sudden" seems to fail on these 3 queries until I disable threaded loading rule:

23:49:57 D Pet : -Loading Pet data...
23:49:57 E Database : Error 2013 running MySQL query: Lost connection to MySQL server during query
SELECT pet_name FROM spawn_pet_names
23:49:57 D Pet : -Load Pet data complete!

23:49:58 I Chat : Loading channels...
23:49:58 E Database : Error 2006 running MySQL query: MySQL server has gone away
SELECT `name`,`password`,`level_restriction`,`classes`,`races` FROM `channels`

This was the first query to new DatabaseNew!

23:50:28 D Login : Looking for Login Zone Updates...
23:50:28 D Login : Looking for Login Appearance Updates...
23:50:28 E Database : Error 2006 running MySQL query: MySQL server has gone away
SELECT ci.id, ci.char_id, ia.equip_type, ia.red, green, ia.blue, ia.highlight_red, ia.highlight_green, ia.highlight_blue
, ci.slot FROM characters c JOIN character_items ci ON c.id = ci.char_id JOIN item_appearances ia ON ci.item_id = ia.ite
m_id WHERE c.deleted = 0 AND ci.type = 'EQUIPPED' AND ( ci.slot <= 8 OR ci.slot = 19 ) AND ci.login_checksum <> CRC32(CR
C32(`ci`.`type`) + CRC32(ci.slot) + CRC32(ci.item_id)) ORDER BY ci.char_id, ci.slot

What I have done --

• Disabled my Windows firewall
  Tried 3 other MySQL servers in my farm
  I have moved the local MySQL to an SSD drive (so I am going to say it's code, and not system performance)
  Increased MySQL memory usage and buffers to the best of my ability

The last thing I did after 20 consecutive failed startups, was disable threaded loading and now 5 times in a row, my world is starting perfectly again.

My thought is, the more functions I refactor to use DatabaseNew, *something* is stampeding over my MySQL connection (the queries using database_new.Select or database_new.Query). No idea what, though I guess I could turn on Query logging in the Database logger. If it weren't 12:15am... maybe I'll do that tomorrow, if you're interested.

[John Adams]

Hmm, just messing around, I commented out the following line in the Items and Spells threaded load functions, and no more errors. still getting errors, but..

Code: Select all

	WorldDatabase db;
	//db.Init();
	db.ConnectNewDatabase();

Is this double-init isn't even needed? Without it, normal SQL does not break.

[John Adams]

Well, screw that theory. 2 more restarts, they still MySQL gone away. I will just run in non-threaded load mode until we figure this out.

[Jabantiz]

I got one of these as well tonight, first time I ever got one.

22:50:31 E Database: Error 2013 running MySQL query: Lost connection to MySQL server during query
SELECT * FROM character_details WHERE char_id = 34 LIMIT 0, 1

22:50:31 E Player: Error loading character_details for 'Jabantiz' (char_id: 34)

As for the double init I did that as that is how it was done in main()

Code: Select all

database.Init();

	if (!database.ConnectNewDatabase())
		return EXIT_FAILURE;

No clue why this showed up all of a sudden, as far as I know no changes where made to the db code. Will try to look into it some tomorrow.

[John Adams]

I'm fairly sure it's because I am slowly converting WorldDatabase functions to use this new method. I've been going slow because of these problems... but if you would look more into just why ThreadedMode seems to cause it more, it might solve the immediate problem.

For now, I am just not running threaded...slowwww, but affective.

Btw, it takes 24 seconds to load 150k items. And 45 seconds to lose 19,000 spells. wtf?

[Scatman]

When you get a chance, or if it happens again, can you please check the MySQL log?

[Scatman]

Hmm, I'm wondering if the multiple connects to MySQL in the different threads is causing the issue. There's no reason to instantiate multiple databases because we're using InnoDB which locks rows as they're being read or written. Therefore only 1 connection can access a row at a time anyway. I couldn't get this to happen, but since it seems to be happening to you frequently John, can you try removing the WorldDatabase db instantiation and db.ConnectNewDatabase() call and see if that helps? You'll need to change the db.* calls to use the global WorldDatabase. There should only be 1 ConnectNewDatabase() where it originally was.

[Jabantiz]

I tried to do it with the original database connections but it gave errors. I think it was the connection was in use on another thread, will get the exact errors in a few mins.

[Jabantiz]

I mainly get this crash

EQ2EmuThreadedLoadCrash.png

Also, if it some how manages to get past that it fails to load stuff

...

18:55:59 W Threaded: Using Threaded loading of static data...
18:55:59 W Thread: Item Loading Thread started.
18:55:59 I Items: Loading Items...
18:55:59 I Spawn: Initializing Spawn Subsystem...
18:55:59 D Command: -Loading Entity Commands...
18:55:59 W Thread: Spell Loading Thread started.
18:55:59 I Spells: Loading Spells...
18:55:59 W Thread: Achievement Loading Thread started.
18:55:59 W Thread: Achievement Loading Thread completed.
18:55:59 D Command: --Loaded 1301 entity command(s)
18:55:59 D NPC: -Loading NPC data...
18:55:59 D Items: Loaded 0 Normal Items
18:56:00 E Items: Error loading `item_details_bauble`, ID: 45000
18:56:00 E Items: Error loading `item_details_bauble`, ID: 45001
18:56:00 E Items: Error loading `item_details_bauble`, ID: 45002
18:56:00 E Items: Error loading `item_details_bauble`, ID: 45003
18:56:00 E Items: Error loading `item_details_bauble`, ID: 45004
18:56:00 E Items: Error loading `item_details_bauble`, ID: 45005
18:56:00 E Items: Error loading `item_details_bauble`, ID: 45006
18:56:00 E Items: Error loading `item_details_bauble`, ID: 45007
18:56:00 E Items: Error loading `item_details_bauble`, ID: 45008
18:56:00 E Items: Error loading `item_details_bauble`, ID: 45009

...

code looks like this now

Code: Select all

ThreadReturnType ItemLoad (void* tmp)
{
	LogWrite(WORLD__WARNING, 0, "Thread", "Item Loading Thread started.");
#ifdef WIN32
	SetThreadPriority(GetCurrentThread(), THREAD_PRIORITY_NORMAL);
#endif
	if (tmp == 0) {
		ThrowError("ItemLoad(): tmp = 0!");
		THREAD_RETURN(NULL);
	}
	World* world = (World*) tmp;
	//WorldDatabase db;
	//db.Init();
	//db.ConnectNewDatabase();
	
	LogWrite(ITEM__INFO, 0, "Items", "Loading Items...");
	database.LoadItemList();
	MasterItemList::ResetUniqueID(database.LoadNextUniqueItemID());

	// Relies on the item list so needs to be in the item thread
	LogWrite(COLLECTION__INFO, 0, "Collect", "Loading Collections...");
	database.LoadCollections();

	LogWrite(MERCHANT__INFO, 0, "Merchants", "Loading Merchants...");
	database.LoadMerchantInformation();

	LogWrite(QUEST__INFO, 0, "Quests", "Loading Quests...");
	database.LoadQuests();

	world->items_loaded = true;
	LogWrite(WORLD__WARNING, 0, "Thread", "Item Loading Thread completed.");
	THREAD_RETURN(NULL);
}

[Scatman]

Ugh.

http://dev.mysql.com/doc/refman/5.1/en/ ... ients.html

[Scatman]

See if the latest on SVN gives you problems still.

[Jabantiz]

I have started up my server about 15 times with no issues, looks like copy and paste kicked my ass again... Real test will be if it works for John.

[Scatman]

Heh yep, I saw that Figured that's what it was.

[John Adams]

I love copy/paste errors... they never happen to me, after all

Edit: Not seeing the issue anymore. I will restart my world a few times just to be sure.

Question though, why on earth would this "suddenly" show up like this? Jab's threaded code has been there for months... and doesn't seem to affect the linux or EQ2TC boxes. Or anyone elses but mine, apparently...


Edit2: Side effect? Everything seems to be loading a whole lot faster now as well. 19.5k spells in 15s vs 90s I reported the other day. Maybe this was fixed elsewhere? Either way, me happy. For now...

[Scatman]

Not sure why it'd randomly start happening to be honest. It wasn't affecting me initially because I didn't have threaded loading on. Once I turned it on I saw the errors.