#2369 Access violation when repeating queries in short interval

[Anonymous]

Originally created by: woutervannifterick

What exact steps will reproduce the problem?
1. go to an empty query tab
2. type the following query: "select 1"
3. press F9, and keep it pressed.

What was the expected output?

The query result to be updated really fast, or if either HeidiSQL or the server cannot cope with the speed, a more descriptive error message.

What happened instead?

Log:
select 1;
/* 0 rows affected, 1 rows found. Duration for 1 query: 0.109 sec. */
select 1;
/* 0 rows affected, 1 rows found. Duration for 1 query: 0.016 sec. */
select 1;
/* 0 rows affected, 1 rows found. Duration for 1 query: 0.125 sec. */
select 1;
/* 0 rows affected, 1 rows found. Duration for 1 query: 0.063 sec. */
select 1;
/* 0 rows affected, 1 rows found. Duration for 1 query: 0.047 sec. */
select 1;
/* 0 rows affected, 1 rows found. Duration for 1 query: 0.125 sec. */
select 1;
/* 0 rows affected, 1 rows found. Duration for 1 query: 0.016 sec. */
select 1;
/* 0 rows affected, 1 rows found. Duration for 1 query: 0.109 sec. */
select 1;
/* 0 rows affected, 1 rows found. Duration for 1 query: 0.062 sec. */
select 1;
/* Connection to 10.1.5.11 closed at 2011-04-04 12:32:42 */
/* Connecting to 10.1.5.11 via MySQL (TCP/IP), username backupuser, using password: Yes ... */
/* Connected. Thread-ID: 81682 */
SHOW STATUS LIKE 'Uptime';
SHOW VARIABLES LIKE 'version_compile_os';
SHOW VARIABLES LIKE 'hostname';
USE `smib`;
select 1;
/* 0 rows affected, 1 rows found. Duration for 1 query: 0.016 sec. */

Bug report:

date/time         : 2011-04-04, 12:21:40, 656ms
computer name     : PEACOCK
user name         : xxx <admin>
registered owner  : xxx
operating system  : Windows XP Service Pack 3 build 2600
system language   : English
system up time    : 17 days 1 hour
program up time   : 1 hour 17 minutes
processors        : 2x Intel(R) Pentium(R) 4 CPU 3.06GHz
physical memory   : 803/3191 MB (free/total)
free disk space   : (C:) 19.91 GB
display mode      : 1600x1200, 32 bit
process id        : $7be4
allocated memory  : 32.57 MB
executable        : heidisql.exe
exec. date/time   : 2011-04-04 10:49
version           : 6.0.0.3749
compiled with     : Delphi XE
madExcept version : 3.0m beta 1
callstack crc     : $cbffec66, $e3131ea7, $e3131ea7
exception number  : 2
exception class   : EAccessViolation
exception message : Access violation at address 038ABDFA in module 'libmysql.dll'. Read of address 00000358.

thread $7dec (TQueryThread):
038abdfa libmysql.dll                       mysql_send_query
038abea0 libmysql.dll                       mysql_real_query
0073e7a1 heidisql.exe dbconnection 1322 +20 TMySQLConnection.Query
006b06e7 heidisql.exe helpers      2947 +35 TQueryThread.Execute
004606cf heidisql.exe madExcept             HookedTThreadExecute
004a883e heidisql.exe Classes               ThreadProc
00407358 heidisql.exe System        548  +0 ThreadWrapper
004605b1 heidisql.exe madExcept             CallThreadProcSafe
0046061b heidisql.exe madExcept             ThreadExceptFrame
>> created by main thread ($7188) at:
006b0476 heidisql.exe helpers      2887  +1 TQueryThread.Create

main thread ($7188):
00000000 heidisql.exe madStackTrace +0 StackAddrToStr
>> stack will be calculated soon

Suggested fix (optional)?

Clues:

- The exception always occurs at the moment that the connection is closed. I don't know why the connection would close, but it might be a clue.

- Older versions didn't seem to have this problem. I think this was introduced when non-blocking queries were introduced, but I'd have to try an older version to confirm that suspicion.

- When I go to the process list, and keep F5 pressed, this error does not occur. It has got to have something to do with the way user queries are processed.

Additional information:
I often run into this problem when I'm monitoring imports. I've got a query like "select count(0) from mytable" to neurotically check if the imports are still working. :)

Version used?
HeidiSQL revision: 6.0.0.3749
MySQL Server version: 5.1.46
Operating system: on workstation: XP pro eng

[Anonymous]

Originally posted by: a...@anse.de

Regarding the access violation, when exactly does it occur in the sequence of log lines?

I am unable to reproduce that here (on Windows 7).

Status: NeedInfo

[Anonymous]

Originally posted by: woutervannifterick

I've tried it on my home computer last night (also XP), and there it behaves the same.

I've enabled logging of all types of events (including debug messages), and did the same: fire "select 1" repeatedly, by keeping the F9 key pressed. When I press it repeatedly I'm unable to trigger this error without getting RSI first. :)

Here's the log (removed HeidiSQL initialization stuff):
---------8<------------------------------------------------
/* Ping server ... */
select 1;
/* 1 rows found. */
/* Result #1 fetched. */
/* Result #1 fetched. */
/* 0 rows affected, 1 rows found. Duration for 1 query: 0.000 sec. */
/* Ping server ... */
select 1;
/* 1 rows found. */
/* Result #1 fetched. */
/* Result #1 fetched. */
/* 0 rows affected, 1 rows found. Duration for 1 query: 0.000 sec. */
/* Ping server ... */
select 1;
/* 1 rows found. */
/* Result #1 fetched. */
/* Result #1 fetched. */
/* 0 rows affected, 1 rows found. Duration for 1 query: 0.015 sec. */
/* Ping server ... */
select 1;
/* 1 rows found. */
/* Result #1 fetched. */
/* Result #1 fetched. */
/* 0 rows affected, 1 rows found. Duration for 1 query: 0.015 sec. */
/* Ping server ... */
select 1;
/* 1 rows found. */
/* Result #1 fetched. */
/* Result #1 fetched. */
/* 0 rows affected, 1 rows found. Duration for 1 query: 0.015 sec. */
/* Ping server ... */
select 1;
/* 1 rows found. */
/* Result #1 fetched. */
/* Result #1 fetched. */
/* 0 rows affected, 1 rows found. Duration for 1 query: 0.016 sec. */
/* Ping server ... */
/* Ping server ... */
select 1;
select 1;
/* SQL Error (2013): Lost connection to MySQL server during query */
/* SQL Error (2006): MySQL server has gone away */

********* EXCEPTION OCCURS HERE *********
********* after chosing "continue in the madexcept window, the following line is added: *********

/* 0 rows affected, 0 rows found. Duration for 0 of 1 query: 0.000 sec. */

------------------------------------------->8--------------

Saved Bugreport.txt contents:
-----8<----------------------------------------------------
date/time         : 2011-04-05, 10:08:14, 968ms
computer name     : PEACOCK
user name         : WouterN <admin>
registered owner  : Gebruiker ARS T&TT
operating system  : Windows XP Service Pack 3 build 2600
system language   : English
system up time    : 17 days 23 hours
program up time   : 33 seconds
processors        : 2x Intel(R) Pentium(R) 4 CPU 3.06GHz
physical memory   : 372/3191 MB (free/total)
free disk space   : (C:) 19.54 GB
display mode      : 1600x1200, 32 bit
process id        : $8a44
allocated memory  : 26.58 MB
executable        : heidisql.exe
exec. date/time   : 2011-04-05 10:05
version           : 6.0.0.3752
compiled with     : Delphi XE
madExcept version : 3.0m beta 1
callstack crc     : $d4c47cfa, $07cdade9, $07cdade9
exception number  : 1
exception class   : EAccessViolation
exception message : Access violation at address 007CE1E6 in module 'heidisql.exe'. Read of address 0000006C.

main thread ($7cbc):
007ce1e6 heidisql.exe Main     2302  +2 GoToErrorPos
007ce376 heidisql.exe Main     2324  +7 TMainForm.FinishedQueryExecution
006b0918 heidisql.exe helpers  2988  +1 TQueryThread.BatchFinished
004a86fb heidisql.exe Classes           CheckSynchronize
005864ae heidisql.exe Forms             TApplication.WndProc
004aaff4 heidisql.exe Classes           StdWndProc
7e418a0b USER32.dll                     DispatchMessageW
00586cfb heidisql.exe Forms             TApplication.ProcessMessage
00586d3e heidisql.exe Forms             TApplication.HandleMessage
00587069 heidisql.exe Forms             TApplication.Run
007f988e heidisql.exe heidisql   65 +15 initialization

[Anonymous]

Originally posted by: a...@anse.de

Thanks a lot for the exact info, should be helpful somehow.

What is mysterious is the first crash is in TMySQLConnection.Query():20 while the second shows up in GoToErrorPos():2. We'll see what I find out.

Summary: Access violation when repeating queries in short interval
Labels: Severity-Problematic
Status: Accepted

[Anonymous]

Originally posted by: a...@anse.de

I can't find anything specific for this issue, and I could still not reproduce it here. But I fixed a couple of other threading problems recently which probably had this side effect in certain cases. Would be nice if you update your build and try if you can reproduce a crash on successive queries. Thanks!

Status: NeedInfo

[Anonymous]

Originally posted by: woutervannifterick

I just grabbed the latest build (3872).

Without debug message logging I can now shoot queries at the server repeatedly without crashing HeidiSQL.
I do seem to get some sort of race condition (note the 2 "select 1" rows without a result in between):

select 1;
/* 0 rows affected, 1 rows found. Duration for 1 query: 0.000 sec. */
select 1;
/* 0 rows affected, 1 rows found. Duration for 1 query: 0.000 sec. */
select 1;
/* 0 rows affected, 1 rows found. Duration for 1 query: 0.000 sec. */
select 1;
/* 0 rows affected, 1 rows found. Duration for 1 query: 0.000 sec. */
select 1;
select 1;
/* 0 rows affected, 1 rows found. Duration for 1 query: 0.000 sec. */
/* 0 rows affected, 1 rows found. Duration for 1 query: 0.000 sec. */
select 1;
/* 0 rows affected, 1 rows found. Duration for 1 query: 0.000 sec. */
select 1;
/* 0 rows affected, 1 rows found. Duration for 1 query: 0.000 sec. */
select 1;
/* 0 rows affected, 1 rows found. Duration for 1 query: 0.016 sec. */
select 1;
/* 0 rows affected, 1 rows found. Duration for 1 query: 0.000 sec. */

----

However, this doesn't cause any crash or other problems as far as I can see. With this build it just keeps running, but I suspect the problem is still out there.

I then turned debug messages on, and then it crashed within the blink of an eye. I didn't get the madexcept popup; the application was just frozen, and all I could do was kill it, and look for the log file.

This is what it looked like:

/* 2011-06-08 21:22:36 [FMU (user@1.1.1.xx)] */ /* mysql_thread_init, thread id #175300 */
/* 2011-06-08 21:22:36 [FMU (user@1.1.1.xx)] */ /* Ping server ... */
/* 2011-06-08 21:22:36 [FMU (user@1.1.1.xx)] */ select 1;
/* 2011-06-08 21:22:36 [FMU (user@1.1.1.xx)] */ /* 1 rows found. */
/* 2011-06-08 21:22:36 [FMU (user@1.1.1.xx)] */ /* mysql_thread_end, thread id #175300 */
/* 2011-06-08 21:22:36 [FMU (user@1.1.1.xx)] */ /* Result #1 fetched. */
/* 2011-06-08 21:22:36 [] */ /* 0 rows affected, 1 rows found. Duration for 1 query: 0.000 sec. */
/* 2011-06-08 21:22:37 [FMU (user@1.1.1.xx)] */ /* mysql_thread_init, thread id #93524 */
/* 2011-06-08 21:22:37 [FMU (user@1.1.1.xx)] */ /* Ping server ... */
/* 2011-06-08 21:22:37 [FMU (user@1.1.1.xx)] */ select 1;
/* 2011-06-08 21:22:37 [FMU (user@1.1.1.xx)] */ /* 1 rows found. */
/* 2011-06-08 21:22:37 [FMU (user@1.1.1.xx)] */ /* mysql_thread_end, thread id #93524 */
/* 2011-06-08 21:22:37 [FMU (user@1.1.1.xx)] */ /* Result #1 fetched. */
/* 2011-06-08 21:22:37 [] */ /* 0 rows affected, 1 rows found. Duration for 1 query: 0.000 sec. */
/* 2011-06-08 21:22:37 [FMU (user@1.1.1.xx)] */ /* mysql_thread_init, thread id #203528 */
/* 2011-06-08 21:22:37 [FMU (user@1.1.1.xx)] */ /* Ping server ... */
/* 2011-06-08 21:22:37 [FMU (user@1.1.1.xx)] */ select 1;
/* 2011-06-08 21:22:37 [FMU (user@1.1.1.xx)] */ /* 1 rows found. */
/* 2011-06-08 21:22:37 [FMU (user@1.1.1.xx)] */ /* mysql_thread_end, thread id #203528 */
/* 2011-06-08 21:22:37 [FMU (user@1.1.1.xx)] */ /* Result #1 fetched. */
/* 2011-06-08 21:22:37 [] */ /* 0 rows affected, 1 rows found. Duration for 1 query: 0.000 sec. */
/* 2011-06-08 21:22:37 [FMU (user@1.1.1.xx)] */ /* mysql_thread_init, thread id #78096 */
/* 2011-06-08 21:22:37 [FMU (user@1.1.1.xx)] */ /* Ping server ... */
/* 2011-06-08 21:22:37 [FMU (user@1.1.1.xx)] */ select 1;
/* 2011-06-08 21:22:37 [FMU (user@1.1.1.xx)] */ /* 1 rows found. */
/* 2011-06-08 21:22:37 [FMU (user@1.1.1.xx)] */ /* mysql_thread_end, thread id #78096 */
/* 2011-06-08 21:22:37 [FMU (user@1.1.1.xx)] */ /* Result #1 fetched. */
/* 2011-06-08 21:22:37 [] */ /* 0 rows affected, 1 rows found. Duration for 1 query: 0.000 sec. */
/* 2011-06-08 21:22:37 [FMU (user@1.1.1.xx)] */ /* mysql_thread_init, thread id #70856 */
/* 2011-06-08 21:22:37 [FMU (user@1.1.1.xx)] */ /* Ping server ... */
/* 2011-06-08 21:22:37 [FMU (user@1.1.1.xx)] */ select 1;
/* 2011-06-08 21:22:37 [FMU (user@1.1.1.xx)] */ /* 1 rows found. */
/* 2011-06-08 21:22:37 [FMU (user@1.1.1.xx)] */ /* mysql_thread_end, thread id #70856 */
/* 2011-06-08 21:22:37 [FMU (user@1.1.1.xx)] */ /* Result #1 fetched. */
/* 2011-06-08 21:22:37 [] */ /* 0 rows affected, 1 rows found. Duration for 1 query: 0.000 sec. */
/* 2011-06-08 21:22:37 [FMU (user@1.1.1.xx)] */ /* mysql_thread_init, thread id #58188 */
/* 2011-06-08 21:22:37 [FMU (user@1.1.1.xx)] */ /* Ping server ... */
/* 2011-06-08 21:22:37 [FMU (user@1.1.1.xx)] */ select 1;
/* 2011-06-08 21:22:37 [FMU (user@1.1.1.xx)] */ /* 1 rows found. */
/* 2011-06-08 21:22:37 [FMU (user@1.1.1.xx)] */ /* mysql_thread_end, thread id #58188 */
/* 2011-06-08 21:22:37 [FMU (user@1.1.1.xx)] */ /* Result #1 fetched. */
/* 2011-06-08 21:22:38 [] */ /* 0 rows affected, 1 rows found. Duration for 1 query: 0.000 sec. */
/* 2011-06-08 21:22:38 [FMU (user@1.1.1.xx)] */ /* mysql_thread_init, thread id #128408 */
/* 2011-06-08 21:22:38 [FMU (user@1.1.1.xx)] */ /* Ping server ... */
/* 2011-06-08 21:22:38 [FMU (user@1.1.1.xx)] */ select 1;
/* 2011-06-08 21:22:38 [FMU (user@1.1.1.xx)] */ /* 1 rows found. */
/* 2011-06-08 21:22:38 [FMU (user@1.1.1.xx)] */ /* mysql_thread_end, thread id #128408 */
/* 2011-06-08 21:22:38 [FMU (user@1.1.1.xx)] */ /* Result #1 fetched. */
/* 2011-06-08 21:22:38 [] */ /* 0 rows affected, 1 rows found. Duration for 1 query: 0.000 sec. */
/* 2011-06-08 21:22:38 [FMU (user@1.1.1.xx)] */ /* mysql_thread_init, thread id #255856 */
/* 2011-06-08 21:22:38 [FMU (user@1.1.1.xx)] */ /* Ping server ... */
/* 2011-06-08 21:22:38 [FMU (user@1.1.1.xx)] */ /* mysql_thread_init, thread id #50552 */
/* 2011-06-08 21:22:38 [FMU (user@1.1.1.xx)] */ select 1;
/* 2011-06-08 21:22:38 [FMU (user@1.1.1.xx)] */ /* Ping server ... */
/* 2011-06-08 21:22:38 [FMU (user@1.1.1.xx)] */ /* 1 rows found. */
/* 2011-06-08 21:22:38 [FMU (user@1.1.1.xx)] */ select 1;
/* 2011-06-08 21:22:38 [FMU (user@1

Note that the last line is incomplete (that's how I found the log).
I did the same thing several times, and every time I get the same type of crash now (HeidiSQL hangs forever). The text that's in the log window in the GUI stops at another place than the log file, and every time the log file ends with an incomplete line.  Maybe that's a clue? Could there be a conflict where two threads try to write to the same log file or something? I'm just guessing here.

[Anonymous]

Originally posted by: a...@anse.de

I can reproduce it when turning on debug logging, and trying quite some hundred "SELECT 1" queries for the 10th time or so. But then it is that crash already described in issue #2410.

Mergedinto: 2410
Status: Duplicate