MySQL Forums
Forum List  »  Perl

Re: DBD::mysql::st execute failed: Lost connection to MySQL server during query
Posted by: Philip Johnson
Date: September 28, 2011 06:19AM

Here's the logging I have at the time for the first crash this morning, for the second before and during the crash, and a few lines after indicating recovery:

00:02:52 5 Processing message
00:02:52 8 Message=*HL7 Transaction Removed*
00:02:52 7 Inserting tran from STAR_HBO into DMS_ADT
00:02:52 7 Inserting tran from STAR_HBO into DTP_ADT
00:02:52 7 Inserting tran from STAR_HBO into HCM_ADT
00:02:52 7 Inserting tran from STAR_HBO into HMM_ADTO
00:02:52 7 Inserting tran from STAR_HBO into MAC_ANC
00:02:52 7 Inserting tran from STAR_HBO into PHS_ADTO
00:02:52 7 Inserting tran from STAR_HBO into SS_ADT
00:02:52 7 Inserting tran from STAR_HBO into WELL_A60O
00:02:52 9 Updated ADT.
00:02:52 7 Inserting tran from STAR_HBO into KHIE_ADTO
00:02:52 7 Inserting tran from STAR_HBO into (Full List) DMS_ADT, DTP_ADT, HCM_ADT, HMM_ADTO, KHIE_ADTO, MAC_ANC, PHS_ADTO, SS_ADT, WELL_A60O
00:02:52 7 In 0 Seconds
00:02:52 9 HL7LIB_SLEEP_SHARE set to 0
00:02:52 9 Past Sleep Paging Logic
00:02:52 5 Commit Done
00:02:52 5 Get top of queue
00:02:52 5 Processing message
00:02:52 8 Message=*HL7 Transaction Removed*
00:02:52 7 Inserting tran from HCM_ORD into HEV_HL7
00:02:52 7 Inserting tran from HCM_ORD into HEV_HL7_TS
00:02:52 7 Inserting tran from HCM_ORD into SBAR_TRAN
00:02:52 7 Inserting tran from HCM_ORD into STAR_CMI
00:02:52 7 Inserting tran from HCM_ORD into WELL_ORDO
00:02:52 7 Inserting tran from HCM_ORD into (Full List) HEV_HL7, HEV_HL7_TS, SBAR_TRAN, STAR_CMI, WELL_ORDO
00:02:52 7 In 0 Seconds
00:02:52 9 HL7LIB_SLEEP_SHARE set to 0
00:02:52 9 Past Sleep Paging Logic
00:02:52 5 Commit Done
00:02:52 5 Get top of queue
00:02:53 5 Processing message
00:02:53 0 Caught a __WARN__
DBD::mysql::st execute failed: Lost connection to MySQL server during query at hl7lib4.pm line 200.
sh: Lock//.lock: Permission denied
00:02:57 3 EngineID =
00:02:57 3 SkipOnFailures =
00:02:57 3 Direction =

There is a maitenance script running that confirms all scripts that should be running are, and spawns them if they are not. That is where the last 3 lines come from, where the script is starting up again.

The line in question in hl7lib4.pm is as follows:
$HL7LIB_UpdateStatus_stmt->execute($pid, $status, $debug, $tran_id, $HEADER{Process});
Which itself is an execution of the following query:
my $HL7LIB_UpdateStatus_stmt = $DBH->prepare("
UPDATE InterfaceStatus SET pid = ?, Status = ?, Debug = ?, LastTransaction = NOW(), Transaction = ? WHERE Process = ?");

The InterfaceStatus table is defined as follows:
CREATE TABLE `HL7Live`.`InterfaceStatus` (
`Process` varchar(10) NOT NULL,
`pid` int(10) unsigned NOT NULL DEFAULT '0',
`Status` varchar(100) NOT NULL DEFAULT 'New Line',
`Debug` int(2) unsigned NOT NULL DEFAULT '0',
`LastTransaction` datetime NOT NULL DEFAULT '0000-00-00 00:00:00',
`Transaction` bigint(20) unsigned NOT NULL DEFAULT '0',
PRIMARY KEY (`Process`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1 MIN_ROWS=100 MAX_ROWS=200;

The table currently has a constant 127 rows in it (at least until we add more interface lines, but that happens one by one over time, there's no chance of the table suddenly having dozens of extra rows without human intervention).

That prepared statement has run over 138,000 times today. For some reason, just that one time, mysql returned the lost connection error.

A second example from later in the morning shows that everything had split-second timing:

07:45:44 5 Processing message
07:45:44 8 Message=*HL7 Transaction Removed*
07:45:44 7 Inserting tran from HCM_ORD into HEV_HL7
07:45:44 7 Inserting tran from HCM_ORD into HEV_HL7_TS
07:45:44 7 Inserting tran from HCM_ORD into PRT_FORM
07:45:44 7 Inserting tran from HCM_ORD into STAR_CMI
07:45:44 7 Inserting tran from HCM_ORD into (Full List) HEV_HL7, HEV_HL7_TS, PRT_FORM, STAR_CMI
07:45:44 7 In 0 Seconds
07:45:44 0 Caught a __WARN__
DBD::mysql::st execute failed: Lost connection to MySQL server during query at ./router4.pl line 62.
sh: Lock//.lock: Permission denied
07:45:44 3 EngineID =
07:45:44 3 SkipOnFailures =
07:45:44 3 Direction =

Again, the connection was lost during the following query:
$ROUTER_behind_sleep_stmt->execute();
Which is the following prepared statement:
my $ROUTER_behind_sleep_stmt = $DBH->prepare("SELECT FLOOR(IFNULL(SQRT(TIMESTAMPDIFF(SECOND, MIN(Time), NOW())-30), 0)) FROM $HEADER{Queue} WHERE status = 'n'");
Where $HEADER{Queue} = "HL7Live.Inbound", with the following definition:
CREATE TABLE `HL7Live`.`Inbound` (
`id` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
`Queue` varchar(20) NOT NULL DEFAULT '',
`Time` datetime NOT NULL DEFAULT '0000-00-00 00:00:00',
`Status` char(1) NOT NULL DEFAULT '',
`TranCode` varchar(8) NOT NULL DEFAULT '',
`Transaction` mediumtext NOT NULL,
PRIMARY KEY (`id`),
KEY `QueueProcess Keys` (`Status`,`Time`),
KEY `Queue_Time` (`Queue`,`Time`),
KEY `Queue_Code` (`Queue`,`TranCode`,`Time`) USING BTREE,
KEY `Status_id` (`Status`,`id`),
KEY `Time_Code` (`Time`,`TranCode`) USING BTREE
) ENGINE=InnoDB AUTO_INCREMENT=261317231 DEFAULT CHARSET=latin1;

That prepared statement has run over 46,000 times today. For some reason, just that one time, mysql returned the lost connection error.


Looking at the slow query log, I have seen a few other oddities as well. it seems that every now and then mysql just kind of freezes for several seconds. I've had Workbench open a few times when it has happened, and there is a commit that seems to be holding things up, but the odd thing is of the statements that then show up in the slow query log, none of them should actually be acquiring table-level locks. Here's an example from this morning:

# Time: 110928 0:18:03
# User@Host: HL7Live[HL7Live] @ localhost []
# Query_time: 3.739729 Lock_time: 0.000055 Rows_sent: 0 Rows_examined: 1
SET timestamp=1317183483;
UPDATE InterfaceStatus SET pid = '24221', Status = 'Got ACK', Debug = '1', LastTransaction = NOW(), Transaction = '250418408' WHERE Process = 'CERME_ADT';
# User@Host: HL7Live[HL7Live] @ localhost []
# Query_time: 3.660665 Lock_time: 0.000057 Rows_sent: 0 Rows_examined: 1
SET timestamp=1317183483;
UPDATE InterfaceStatus SET pid = '25487', Status = 'Getting Tran', Debug = '3', LastTransaction = NOW(), Transaction = '25939798' WHERE Process = 'STAR_CMO';
# User@Host: HL7Live[HL7Live] @ localhost []
# Query_time: 3.728381 Lock_time: 0.000057 Rows_sent: 0 Rows_examined: 1
SET timestamp=1317183483;
UPDATE InterfaceStatus SET pid = '21897', Status = 'Got ACK', Debug = '1', LastTransaction = NOW(), Transaction = '250570470' WHERE Process = 'EP_ADT';
# User@Host: HL7Live[HL7Live] @ localhost []
# Query_time: 3.069095 Lock_time: 0.000055 Rows_sent: 0 Rows_examined: 1
SET timestamp=1317183483;
UPDATE InterfaceStatus SET pid = '25823', Status = 'Getting Tran', Debug = '3', LastTransaction = NOW(), Transaction = '0' WHERE Process = 'HMM_PYXI';
# User@Host: HL7Live[HL7Live] @ localhost []
# Query_time: 3.571474 Lock_time: 0.000057 Rows_sent: 0 Rows_examined: 1
SET timestamp=1317183483;
UPDATE InterfaceStatus SET pid = '12688', Status = 'Got ACK', Debug = '1', LastTransaction = NOW(), Transaction = '250489554' WHERE Process = 'VAR_ADT';
# User@Host: HL7Live[HL7Live] @ localhost []
# Query_time: 3.713773 Lock_time: 0.000050 Rows_sent: 0 Rows_examined: 1
SET timestamp=1317183483;
UPDATE InterfaceStatus SET pid = '16701', Status = 'Got ACK', Debug = '1', LastTransaction = NOW(), Transaction = '251064964' WHERE Process = 'HCM_ADT';
# User@Host: HL7Live[HL7Live] @ localhost []
# Query_time: 3.511983 Lock_time: 0.000053 Rows_sent: 0 Rows_examined: 1
SET timestamp=1317183483;
UPDATE InterfaceStatus SET pid = '18449', Status = 'Got ACK', Debug = '1', LastTransaction = NOW(), Transaction = '250897348' WHERE Process = 'HPF_ADT';
# User@Host: HL7Live[HL7Live] @ localhost []
# Query_time: 3.730660 Lock_time: 0.000051 Rows_sent: 0 Rows_examined: 1
SET timestamp=1317183483;
UPDATE InterfaceStatus SET pid = '27566', Status = 'Got ACK', Debug = '1', LastTransaction = NOW(), Transaction = '250412174' WHERE Process = 'PLUS_OUT';
# User@Host: HL7Live[HL7Live] @ localhost []
# Query_time: 3.263523 Lock_time: 0.000071 Rows_sent: 0 Rows_examined: 0
SET timestamp=1317183483;
INSERT INTO Inbound (Queue, Time, Status, TranCode, Transaction) VALUES ('STAR_HBO', NOW(), 'n', 'A03', '*HL7 Transaction Removed*');

Each of the updates into InterfaceStatus should have been a row-level lock, and as I have innodb_autoinc_lock_mode = 2, the insert also should not be generating a table lock. All of the lines also report almost no lock time whatsoever, so it doesn't appear that mysql is deadlocking.

The only thing in my mysql-error.log file since the server rebooted is the following:
110730 7:43:24 [Warning] IP address '172.20.10.8' could not be resolved: no reverse address mapping.
110804 20:11:48 [Warning] IP address '172.20.10.1' could not be resolved: no reverse address mapping.
110819 15:05:46 [Warning] IP address '172.20.2.84' could not be resolved: no reverse address mapping.
110927 17:34:55 [Warning] IP address '172.20.10.3' could not be resolved: no reverse address mapping.

Options: ReplyQuote




Sorry, you can't reply to this topic. It has been closed.

Content reproduced on this site is the property of the respective copyright holders. It is not reviewed in advance by Oracle and does not necessarily represent the opinion of Oracle or any other party.