Queries waiting for mutex
Hello all,
Yesterday afternoon we ran into a problem. All sessions selecting or modifying
data stopped responding to users. Onstat -u showed all of these sessions in a
status of waiting for mutex 'S--P---'. After gathering onstat -a and onstat -g
all information, I restarted Informix. For the time, database access and
processing looks normal. I've opened a PMR and tech support has the onstat
information for analysis. I'm also reviewing these onstats. According to the
-g lmx output all the sessions backlogged on the same mutex which was held by
session ID 46. However, session ID 46 doesn't appear in the onstat -u output.
Are there known Informix processes that are assigned session ID's that don't
appear in onstat -u?
If so, are there other onstats that would show these sessions?
Any other suggestions for review?
Thanks,
Dave Griffen
IDS 11.50.FC5
HP-UX 11.23 ia64
Hi,
There a no Informix processes with sessions, only threads. And there are
quite a few threads with no session: page cleaners, log writers, btree
cleaners, and more. Take a look at onstat -g ath (All THreads) to see the
full set. You may have one of those internal threads causing a problem.
Also, onstat -g wai shows the threads waiting for something. That will
probably let you see the problem more easily.
Cheers,
Dick Snoke
IBM ChannelWorks
dsnoke@us.ibm.com
(404) 487-1595
From: "DAVE GRIFFEN" <dgriffen@finishline.com>
To: ids@iiug.org
Date: 10/01/2010 02:11 PM
Subject: Queries waiting for mutex [21504]
Sent by: ids-bounces@iiug.org
Hello all,
Yesterday afternoon we ran into a problem. All sessions selecting or
modifying
data stopped responding to users. Onstat -u showed all of these sessions
in a
status of waiting for mutex 'S--P---'. After gathering onstat -a and
onstat -gall information, I restarted Informix. For the time, database access and
processing looks normal. I've opened a PMR and tech support has the onstat
information for analysis. I'm also reviewing these onstats. According to
the
-g lmx output all the sessions backlogged on the same mutex which was held
by
session ID 46. However, session ID 46 doesn't appear in the onstat -u
output.
Are there known Informix processes that are assigned session ID's that
don't
appear in onstat -u?
If so, are there other onstats that would show these sessions?
Any other suggestions for review?
Thanks,
Dave Griffen
IDS 11.50.FC5
HP-UX 11.23 ia64
*******************************************************************************
Forum Note: Use "Reply" to post a response in the discussion forum.
I searched around and copied a historical response info by Jacques
Renaut.
You may have a look and see if it can give you some tips.
Frank
Frank wrote:
(4) mutex holder ??? it shows session 88852, but onstat -g ses 88852 shows
nothing ( see below)
informix@dora $ onstat -g lmx
IBM Informix Dynamic Server Version 11.10.UC2 -- On-Line -- Up 4 days
03:03:29 -- 2120544 Kbytes
Locked mutexes:
mid addr name holder lkcnt waiter waittime
13 407aa028 session 88852 0 13 48356
Response:
The "88852" is not the session number for the holder of the mutex. It's the
thread id, as is the waiter field. So instead of looking at onstat -g ses
for
that number, you need to look at onstat -g ath and get the matching thread
id
(first column output). Then take the value for the rstcb column from that
onstat -g ath output and match that to the 1st column of the onstat -u
output,and then use the session number from the onstat -u. You would probably also
want to get onstat -g stk <thread id> output for the holder of the mutex.
This
looks like some sort of mutex deadlock, but onstat -g stk 88852 output along
with onstat -g ses output for the correct session of the holder would
probably
help.
Jacques Renaut
IBM Informix Advanced Support
APD Team
*******************************************************************************
Forum Note: Use "Reply" to post a response in the discussion forum.
Reply
Forward
Reply
|
FRANK to ids
show details Aug 17
Thanks a lot Jacques!!
I did the trace and found the session( see detail info_1 below). Its
father process 733226 had already been stopped. But the session is
still there and running... , onmode -z 86754 hangs.,
So the final solution is to reboot the IDS ?
By the way, what does the "Changing data structure forced command
termination." mean at the end of Info_2 below?
Thanks,
Frank
++++++++++++++++++++++++++ Info_1 ++++++++++++++++++++++++++++++
informix@dora $ onstat -g lmx
IBM Informix Dynamic Server Version 11.10.UC2 -- On-Line -- Up 4 days
04:12:29 -- 2120544 Kbytes
Locked mutexes:
mid addr name holder lkcnt waiter waittime
13 407aa028 session 88852 0 13 52496
88609 52408
88607 52408
73925 51426
73927 51426
73926 51426
15 50441
86531 47219
84681 47219
91 44781
88399 40019
86532 40019
76 7356
1853 6495
1852 6495
1854 6495
1844 5615
1848 5615
1839 5615
Number of mutexes on VP free lists: 4317
informix@dora $ onstat -g ath | grep 88852
88852 944b8168 9073dcf0 1 running 5cpu sqlexec
informix@dora $ onstat -u | grep 9073dcf0
9073dcf0 ---PR-- 86754 informix 7 0 0 1 0 0
informix@dora $ onstat -g ses 86754
IBM Informix Dynamic Server Version 11.10.UC2 -- On-Line -- Up 4 days
04:14:50 -- 2120544 Kbytes
session #RSAM total used
dynamic
id user tty pid hostname threads memory memory
explain
86754 informix 7 733226 dora 1 491520 475944
off
tid name rstcb flags curstk status
88852 sqlexec 9073dcf0 ---PR-- 6248 running
Memory pools count 2
name class addr totalsize freesize #allocfrag #freefrag
86754 V 93bea020 487424 13144 234 18
86754*O0 V 940fb020 4096 2432 1 1
name free used name free used
overhead 0 3328 mtmisc 0 40
scb 0 96 opentable 0 5288
filetable 0 1016 log 0 14096
temprec 0 96840 keys 0 352
ralloc 0 317880 gentcb 0 1224
ostcb 0 2736 sqscb 0 15240
sql 0 40 rdahead 0 6208
hashfiletab 0 280 osenv 0 2344
buft_buffer 0 4184 sqtcb 0 3640
fragman 0 904 sapi 0 40
udr 0 128
sqscb info
scb sqscb optofc pdqpriority sqlstats optcompind directives
945be060 93b33018 0 0 0 0 1
Sess SQL Current Iso Lock SQL ISAM F.E.
Id Stmt type Database Lvl Mode ERR ERR Vers
Explain
86754 SELECT sysmaster CR Not Wait 0 0 9.30
Off
Current statement name : c_000000000
Current SQL statement :
SELECT a.scs_sessionid, a.scs_currdb, a.scs_isolationlevel,
a.scs_sqlstatement FROM syssqlcurses a where a.scs_sessionid <>
DBINFO('sessionid') and length(a.scs_sqlstatement) >1
Last parsed SQL statement :
SELECT a.scs_sessionid, a.scs_currdb, a.scs_isolationlevel,
a.scs_sqlstatement FROM syssqlcurses a where a.scs_sessionid <>
DBINFO('sessionid') and length(a.scs_sqlstatement) >1
informix@dora $ onstat -g stk 88852
IBM Informix Dynamic Server Version 11.10.UC2 -- On-Line -- Up 4 days
04:16:35 -- 2120544 Kbytes
Stack for thread: 88852 sqlexecbase: 0x93bb2000
len: 69632
pc: 0x1004b164
tos: 0x93bc1798
state: running
vp: 5
0x00000000
++++++++++++++++++++++++++++ info_2 ++++++++++++++++++++++++++++
IBM Informix Dynamic Server Version 11.10.UC2 -- On-Line -- Up 4 days
04:33:24 -- 2120544 Kbytes
session #RSAM total used
dynamic
id user tty pid hostname threads memory memory
explain
73283 saatmgr - 4771938 ɧl"¸¹ 1 86016 17552
off
tid name rstcb flags curstk status
73927 sqlexec 9073a3c0 S------ 3288 mutex wait(session)
Memory pools count 2
name class addr totalsize freesize #allocfrag #freefrag
73283 V 93c33020 81920 66032 164 47
73283*O0 V 93beb020 4096 2432 1 1
name free used name free used
overhead 0 3328 scb 0 96
gentcb 0 648 sqscb 0 10928
osenv 0 2456 sqtcb 0 96
sqscb info
scb sqscb optofc pdqpriority sqlstats optcompind directives
932f0060 9337d018 0 0 0 0 1
Sess SQL Current Iso Lock SQL ISAM F.E.
Id Stmt type Database Lvl Mode ERR ERR Vers
Explain
73283 Ã2`'dÁ CR Wait 0 0 9.29
Off
Changing data structure forced command termination.
++++++++++++++++++++++++++++++++++++++++++++++++++++++++
- Show quoted text -
On Fri, Oct 1, 2010 at 2:11 PM, DAVE GRIFFEN <dgriffen@finishline.com>wrote:
> Hello all,
>
> Yesterday afternoon we ran into a problem. All sessions selecting or
> modifying
> data stopped responding to users. Onstat -u showed all of these sessions in
> a
> status of waiting for mutex 'S--P---'. After gathering onstat -a and onstat
> -g
> all information, I restarted Informix. For the time, database access and
> processing looks normal. I've opened a PMR and tech support has the onstat
> information for analysis. I'm also reviewing these onstats. According to
> the
> -g lmx output all the sessions backlogged on the same mutex which was held
> by
> session ID 46. However, session ID 46 doesn't appear in the onstat -u
> output.
>
> Are there known Informix processes that are assigned session ID's that
> don't
> appear in onstat -u?
> If so, are there other onstats that would show these sessions?
>
> Any other suggestions for review?
>
> Thanks,
> Dave Griffen
>
> IDS 11.50.FC5
> HP-UX 11.23 ia64
>
>
>
>
*******************************************************************************
> Forum Note: Use "Reply" to post a
We had a similar problem before. Finally, we found the following high
frequent running SQL ( a in house created job for monitoring ) of a
informix session was the cause.
We have not seen such problem since we stopped that SQL job.
By the way, we are IDS11.10 UC2, AIX 5.3
Frank
SELECT a.scs_sessionid, a.scs_currdb, a.scs_isolationlevel,
a.scs_sqlstatement FROM syssqlcurses a where a.scs_sessionid <>
DBINFO('sessionid') and length(a.scs_sqlstatement) >1
On Fri, Oct 1, 2010 at 2:54 PM, FRANK <yunyaoqu@gmail.com> wrote:
> I searched around and copied a historical response info by Jacques
> Renaut.
>
> You may have a look and see if it can give you some tips.
>
> Frank
>
>
> Frank wrote:
> (4) mutex holder ??? it shows session 88852, but onstat -g ses 88852 shows
> nothing ( see below)
>
> informix@dora $ onstat -g lmx
>
> IBM Informix Dynamic Server Version 11.10.UC2 -- On-Line -- Up 4 days
> 03:03:29 -- 2120544 Kbytes>
> Locked mutexes:
> mid addr name holder lkcnt waiter waittime
> 13 407aa028 session 88852 0 13 48356
>
> Response:
>
> The "88852" is not the session number for the holder of the mutex. It's the
> thread id, as is the waiter field. So instead of looking at onstat -g ses
> for
> that number, you need to look at onstat -g ath and get the matching thread
> id
> (first column output). Then take the value for the rstcb column from that
> onstat -g ath output and match that to the 1st column of the onstat -u
> output,> and then use the session number from the onstat -u. You would probably also
> want to get onstat -g stk <thread id> output for the holder of the mutex.
> This
> looks like some sort of mutex deadlock, but onstat -g stk 88852 output
> along
> with onstat -g ses output for the correct session of the holder would
> probably
> help.
>
> Jacques Renaut
> IBM Informix Advanced Support
> APD Team
>
>
>
>
*******************************************************************************
>
> Forum Note: Use "Reply" to post a response in the discussion forum.
>
> Reply
>
> Forward
>
>
>
>
> Reply
> |
> FRANK to ids
> show details Aug 17
>
>
> Thanks a lot Jacques!!
>
> I did the trace and found the session( see detail info_1 below). Its
> father process 733226 had already been stopped. But the session is
> still there and running... , onmode -z 86754 hangs.,
>
> So the final solution is to reboot the IDS ?
>
>
> By the way, what does the "Changing data structure forced command
> termination." mean at the end of Info_2 below?
>
>
> Thanks,
> Frank
>
> ++++++++++++++++++++++++++ Info_1 ++++++++++++++++++++++++++++++
>
>
> informix@dora $ onstat -g lmx
>
> IBM Informix Dynamic Server Version 11.10.UC2 -- On-Line -- Up 4 days
> 04:12:29 -- 2120544 Kbytes>
>
> Locked mutexes:
> mid addr name holder lkcnt waiter waittime
> 13 407aa028 session 88852 0 13 52496
> 88609 52408
> 88607 52408
> 73925 51426
> 73927 51426
> 73926 51426
> 15 50441
> 86531 47219
> 84681 47219
> 91 44781
> 88399 40019
> 86532 40019
> 76 7356
> 1853 6495
> 1852 6495
> 1854 6495
> 1844 5615
> 1848 5615
> 1839 5615
>
> Number of mutexes on VP free lists: 4317
>
> informix@dora $ onstat -g ath | grep 88852
> 88852 944b8168 9073dcf0 1 running 5cpu sqlexec
> informix@dora $ onstat -u | grep 9073dcf0
> 9073dcf0 ---PR-- 86754 informix 7 0 0 1 0 0
> informix@dora $ onstat -g ses 86754
>
> IBM Informix Dynamic Server Version 11.10.UC2 -- On-Line -- Up 4 days
> 04:14:50 -- 2120544 Kbytes>
> session #RSAM total used
> dynamic
> id user tty pid hostname threads memory memory
> explain
> 86754 informix 7 733226 dora 1 491520 475944
> off
>
> tid name rstcb flags curstk status
> 88852 sqlexec 9073dcf0 ---PR-- 6248 running
>
> Memory pools count 2
> name class addr totalsize freesize #allocfrag #freefrag
> 86754 V 93bea020 487424 13144 234 18
> 86754*O0 V 940fb020 4096 2432 1 1
>
> name free used name free used
> overhead 0 3328 mtmisc 0 40
> scb 0 96 opentable 0 5288
> filetable 0 1016 log 0 14096
> temprec 0 96840 keys 0 352
> ralloc 0 317880 gentcb 0 1224
> ostcb 0 2736 sqscb 0 15240
> sql 0 40 rdahead 0 6208
> hashfiletab 0 280 osenv 0 2344
> buft_buffer 0 4184 sqtcb 0 3640
> fragman 0 904 sapi 0 40
> udr 0 128
>
> sqscb info
> scb sqscb optofc pdqpriority sqlstats optcompind directives
> 945be060 93b33018 0 0 0 0 1
>
> Sess SQL Current Iso Lock SQL ISAM F.E.
> Id Stmt type Database Lvl Mode ERR ERR Vers
> Explain
> 86754 SELECT sysmaster CR Not Wait 0 0 9.30
> Off
>
> Current statement name : c_000000000
>
> Current SQL statement :
> SELECT a.scs_sessionid, a.scs_currdb, a.scs_isolationlevel,> a.scs_sqlstatement FROM syssqlcurses a where a.scs_sessionid <>
> DBINFO('sessionid') and length(a.scs_sqlstatement) >1>
> Last parsed SQL statement :
> SELECT a.scs_sessionid, a.scs_currdb, a.scs_isolationlevel,> a.scs_sqlstatement FROM syssqlcurses a where a.scs_sessionid <>
> DBINFO('sessionid') and length(a.scs_sqlstatement) >1>
>
> informix@dora $ onstat -g stk 88852
>
> IBM Informix Dynamic Server Version 11.10.UC2 -- On-Line -- Up 4 days
> 04:16:35 -- 2120544 Kbytes>
> Stack for thread: 88852 sqlexec> base: 0x93bb2000
> len: 69632
> pc: 0x1004b164
> tos: 0x93bc1798
> state: running
> vp: 5
>
> 0x00000000
>
> ++++++++++++++++++++++++++++ info_2 ++++++++++++++++++++++++++++
>
> IBM Informix Dynamic Server Version 11.10.UC2 -- On-Line -- Up 4 days
> 04:33:24 -- 2120544 Kbytes>
> session #RSAM total used
> dynamic
> id user tty pid hostname threads memory memory
> explain
> 73283 saatmgr - 4771938 ɧl"¸¹ 1 86016 17552
> off
>
> tid name rstcb flags curstk status
> 73927 sqlexec 9073a3c0 S------ 3288 mutex wait(session)
>
> Memory pools count 2
> name class addr totalsize freesize #allocfrag #freefrag
> 73283 V 93c33020 81920 66032 164 47
> 73283*O0 V 93beb020 4096 2432 1 1
>
> name free used name free used
> overhead 0 3328 scb 0 96
> gentcb 0 648 sqscb 0 10928
> osenv 0 2456 sqtcb 0 96
>
> sqscb info
> scb sqscb optofc pdqpriority sqlstats optcompind directives
> 932f0060 9337d018 0 0 0 0 1
>
> Sess SQL Current Iso Lock SQL ISAM F.E.
> Id Stmt type Database Lvl Mode ERR ERR Vers
> Explain
> 73283 Ã2`'dÁ CR Wait 0 0 9.29
> Off
> Changing data structure forced command termination.
>
> ++++++++++++++++++++++++++++++++++++++++++++++++++++++++
> - Show quoted text -
>
>
>
>
> On Fri, Oct 1, 2010 at 2:11 PM, DAVE GRIFFEN <dgriffen@finishline.com>wrote:
>
>> Hello all,
>>
>> Yesterday afternoon we ran into a problem. All sessions selecting or
>> modifying
>> data stopped responding to users. Onstat -u showed all of these sessions
>> in a
>> status of waiting for mutex 'S--P---'. After gather
Thanks for the reference Frank.
I suppose I'm not the only one who got the wrong impression from the Admin
Reference documentation on onstat -g lmx stating that the holder column was
the "Session ID of the thread holding the mutex". Sounds like the holder
column is Thread ID and not the Session ID.
Onstat -g ath shows thread 46 has an rstcb 0.
FRANK Wrote:
-----------------------------------------------------------------------------
I searched around and copied a historical response info by Jacques
Renaut.
You may have a look and see if it can give you some tips.
Frank
Frank wrote:
(4) mutex holder ??? it shows session 88852, but onstat -g ses 88852 shows
nothing ( see below)
informix@dora $ onstat -g lmx
IBM Informix Dynamic Server Version 11.10.UC2 -- On-Line -- Up 4 days
03:03:29 -- 2120544 Kbytes
Locked mutexes:
mid addr name holder lkcnt waiter waittime
13 407aa028 session 88852 0 13 48356
Response:
The "88852" is not the session number for the holder of the mutex. It's the
thread id, as is the waiter field. So instead of looking at onstat -g ses
for
that number, you need to look at onstat -g ath and get the matching thread
id
(first column output). Then take the value for the rstcb column from that
onstat -g ath output and match that to the 1st column of the onstat -u
output,and then use the session number from the onstat -u. You would probably also
want to get onstat -g stk <thread id> output for the holder of the mutex.
This
looks like some sort of mutex deadlock, but onstat -g stk 88852 output along
with onstat -g ses output for the correct session of the holder would
probably
help.
Jacques Renaut
IBM Informix Advanced Support
APD Team
-----------------------------------------------------------------------------