一个诡异问题的分析过程

By cui hua on January 23, 2009 4:16 PM | No Comments | No TrackBacks

今天我一个同事写信问我：

"

在10.1.15.57的ARMSHIS上

我设置了RESOURCE_LIMIT=TRUE和XBSYL的IDLE_TIME=1分钟

我用PL/SQL Developer运行一个时间超过6分钟的SQL出现

ORA-02396　exceeded maximum idle time的错误。

但是我从后台运行没什么问题。

PL/SQL Developer也设置了AUTOCOMMIT，奇怪，好像就是超过一定的时间，比如说6分钟就OVER了。

SQL:

begin

for i in 1..400 loop

insert into f1 select * from dba_objects;

end loop;

end;
"

 

接到上述email，我首先尝试在我本机重现上述问题，在PL/SQL Developer中开了一个command window执行上述匿名pl/sql块，执行成功，没有任何问题。

然后我在MSN上跟我那位同事沟通，她说她的PL/SQL Developer是7.0.3的版本，于是我尝试安装7.0.3版后执行上述匿名pl/sql块，依然能够成功执行。

再仔细问她是怎样执行上述匿名pl/sql块的，她截了图发给我，我一看，原来是在PL/SQL Developer的sql window中执行的。

好了，马上在我本机开一个sql window后执行上述匿名pl/sql块，这下问题重现了！

 

去ARMSHIS中看了一下alert log，从里面可以看到：

Thu Jan 22 12:44:48 2009

SMON: Parallel transaction recovery tried

Thu Jan 22 12:45:46 2009

 

这里我演示一下我分析上述问题的过程：

先打开一个PL/SQL Developer 6.0.5，接着打开一个command window和一个sql window，在sql window中执行上述匿名pl/sql块，同时在上述command window中观察v$session的状况，在command window中观察的步骤如下所示：

SQL> conn xbsyl/gg@armshis;

Connected to Oracle9i Enterprise Edition Release 9.2.0.6.0

Connected as xbsyl

 

SQL> select profile,resource_name,limit from dba_profiles where resource_name='IDLE_TIME';

 

PROFILE                        RESOURCE_NAME                    LIMIT

------------------------------ -------------------------------- ----------------------------------------

DEFAULT                        IDLE_TIME                        UNLIMITED

D1                             IDLE_TIME                        1

 

SQL> select username,profile from dba_users where username='XBSYL';

 

USERNAME                       PROFILE

------------------------------ ------------------------------

XBSYL                          D1

 

SQL> select sid,username,status,machine,program,action from v$session;

 

       SID USERNAME                       STATUS   MACHINE                                                          PROGRAM                                          ACTION

---------- ------------------------------ -------- ---------------------------------------------------------------- ------------------------------------------------ --------------------------------

         1                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (PMON)                        

         2                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (DBW0)                        

         3                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (LGWR)                        

         4                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (CKPT)                        

         5                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (SMON)                        

         6                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (RECO)                         

         7                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (CJQ0)                        

         8                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (QMN0)                        

         9 XBSYL                          ACTIVE   ACCA\Y8908CUIHUA                                                 plsqldev.exe                                     Command Window - New

14 XBSYL                          ACTIVE   ACCA\Y8908CUIHUA                                                 plsqldev.exe                                      SQL Window - New

        18 XBSYL                          INACTIVE   ACCA\Y8908CUIHUA                                                 plsqldev.exe                                     Main session

 

11 rows selected

我们可以从结果中看到虽然我们只开了一个command window和一个sql window，但是PL/SQL Developer实际上在oracle那边起了3个session，有一个是main session，它的状态从一开始就是inactive。

 

然后我开始每隔10秒钟就查看一下v$session（目的是不让command window所在的session过期），大概1分钟之后v$session中PL/SQL Developer的main session的状态发生了变化，结果如下：

SQL> select sid,username,status,machine,program,action from v$session;

 

       SID USERNAME                       STATUS   MACHINE                                                          PROGRAM                                          ACTION

---------- ------------------------------ -------- ---------------------------------------------------------------- ------------------------------------------------ --------------------------------

         1                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (PMON)                        

         2                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (DBW0)                        

         3                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (LGWR)                        

         4                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (CKPT)                        

         5                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (SMON)                        

         6                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (RECO)                        

         7                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (CJQ0)                        

         8                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (QMN0)                        

         9 XBSYL                          ACTIVE   ACCA\Y8908CUIHUA                                                 plsqldev.exe                                     Command Window - New

14 XBSYL                          ACTIVE   ACCA\Y8908CUIHUA                                                 plsqldev.exe                                      SQL Window - New

        18 XBSYL                          SNIPED   ACCA\Y8908CUIHUA                                                 plsqldev.exe                                     Main session

 

11 rows selected

SNIPED表示这个main session已经过期，是可以被PMON给杀掉的。

 

接续观察v$session，发现在几分钟之后，Main session居然真被PMON杀掉了。与此同时，执行上述匿名pl/sql块的sql window报错ORA-02396　exceeded maximum idle time，这个sql window所在的session的状态也变成inactive，如下所示：

SQL> select sid,username,status,machine,program,action from v$session;

 

       SID USERNAME                       STATUS   MACHINE                                                          PROGRAM                                          ACTION

---------- ------------------------------ -------- ---------------------------------------------------------------- ------------------------------------------------ --------------------------------

         1                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (PMON)                        

         2                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (DBW0)                        

         3                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (LGWR)                        

         4                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (CKPT)                         

         5                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (SMON)                        

         6                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (RECO)                        

         7                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (CJQ0)                         

         8                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (QMN0)                        

         9 XBSYL                          ACTIVE   ACCA\Y8908CUIHUA                                                 plsqldev.exe                                     Command Window - New

14 XBSYL                          INACTIVE   ACCA\Y8908CUIHUA                                                 plsqldev.exe                                      SQL Window - New

 

10 rows selected

 

测试进行到这儿，我们已经明白了出现上述问题的原因，因为PL/SQL Developer的main session被PMON杀掉了，所以导致执行匿名PL/SQL块的sql window报错退出。

 

现在我们来看看为什么在command window中执行上述同样的匿名pl/sql块却可以执行成功呢，而且屡试不爽？

 

我们保持在上述6.0.3的PL/SQL Developer的command window中每隔10秒就执行一次查询v$session的操作，同时打开一个7.0.3的PL/SQL Developer。在这个7.0.3的PL/SQL Developer的环境中打开一个command window，然后执行上述匿名pl/sql块，如下所示：

SQL> conn xbsyl/gg@armshis;

Connected to Oracle9i Enterprise Edition Release 9.2.0.6.0

Connected as xbsyl

 

SQL> begin

  2  for i in 1..400 loop

  3  insert into f1 select * from dba_objects;

  4  end loop;

  5  end;

  6  /

 

然后我们开始在6.0.3的PL/SQL Developer的command window中每隔10秒就执行一次查询v$session的操作，如下所示：

SQL> select sid,username,status,machine,program,action from v$session;

 

       SID USERNAME                       STATUS   MACHINE                                                          PROGRAM                                          ACTION

---------- ------------------------------ -------- ---------------------------------------------------------------- ------------------------------------------------ --------------------------------

         1                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (PMON)                        

         2                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (DBW0)                        

         3                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (LGWR)                        

         4                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (CKPT)                        

         5                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (SMON)                        

         6                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (RECO)                        

         7                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (CJQ0)                        

         8                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (QMN0)                        

         9 XBSYL                          ACTIVE   ACCA\Y8908CUIHUA                                                 plsqldev.exe                                     Command Window - New

        14 XBSYL                          INACTIVE ACCA\Y8908CUIHUA                                                 plsqldev.exe                                     Main session

        22 XBSYL                          ACTIVE   ACCA\Y8908CUIHUA                                                 plsqldev.exe                                     Command Window - New

 

11 rows selected

这和我们预想的一样，有一个inactive的main session，有两个active的command window所在的session。

 

大概1分钟之后v$session中那个7.0.3的PL/SQL Developer的main session的状态发生了变化，结果如下：

SQL> select sid,username,status,machine,program,action from v$session;

 

       SID USERNAME                       STATUS   MACHINE                                                          PROGRAM                                          ACTION

---------- ------------------------------ -------- ---------------------------------------------------------------- ------------------------------------------------ --------------------------------

         1                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (PMON)                        

         2                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (DBW0)                        

         3                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (LGWR)                        

         4                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (CKPT)                        

         5                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (SMON)                        

         6                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (RECO)                        

         7                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (CJQ0)                        

         8                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (QMN0)                        

         9 XBSYL                          ACTIVE   ACCA\Y8908CUIHUA                                                 plsqldev.exe                                     Command Window - New

        14 XBSYL                          SNIPED   ACCA\Y8908CUIHUA                                                 plsqldev.exe                                     Main session

        22 XBSYL                          ACTIVE   ACCA\Y8908CUIHUA                                                 plsqldev.exe                                     Command Window - New

 

11 rows selected

 

接着我还是每隔10秒钟就在6.0.3的那个PL/SQL Developer的command window窗口中不断查询v$session，我发现main session的状态虽然始终是SNIPED，但它却一直还在，没有被PMON给杀掉，直到7.0.3的那个PL/SQL Developer的执行上述匿名pl/sql块的command window成功执行完毕，它所在的session的状态也变成了inactive，如下所示：

SQL> select sid,username,status,machine,program,action from v$session;

 

       SID USERNAME                       STATUS   MACHINE                                                          PROGRAM                                          ACTION

---------- ------------------------------ -------- ---------------------------------------------------------------- ------------------------------------------------ --------------------------------

         1                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (PMON)                        

         2                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (DBW0)                        

         3                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (LGWR)                         

         4                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (CKPT)                        

         5                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (SMON)                        

         6                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (RECO)                        

         7                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (CJQ0)                        

         8                                ACTIVE   P550_04_LA                                                       oracle@P550_04_LA (QMN0)                        

         9 XBSYL                          ACTIVE   ACCA\Y8908CUIHUA                                                 plsqldev.exe                                     Command Window - New

        14 XBSYL                          SNIPED   ACCA\Y8908CUIHUA                                                 plsqldev.exe                                     Main session

        22 XBSYL                          INACTIVE ACCA\Y8908CUIHUA                                                 plsqldev.exe                                     Command Window - New

 

11 rows selected

 

这时候我们再去7.0.3的那个PL/SQL Developer的command window中查看一下上述匿名pl/sql块的执行情况，发现确实执行成功了，如下所示：

SQL> begin

  2  for i in 1..400 loop

  3  insert into f1 select * from dba_objects;

  4  end loop;

  5  end;

  6  /

 

PL/SQL procedure successfully completed

 

SQL> commit;

 

Commit complete

 

至此，上述诡异问题已经被我分析完毕。

总的来说，出现上述现象的根本原因在于在sql window的情况下，PL/SQL Developer的 main session过期后会被PMON杀掉，即使sql window还处于active的状态；而在command window的情况下，PL/SQL Developer的 main session虽然还是会过期，但是在command window还是处于active的情况下的时候是不会被PMON给杀掉的！

 

知道了原因，处理上述问题就好办了，要避免上述问题，要么你直接在sqlplus中执行匿名pl/sql块，要么你在PL/SQL Developer的command window中执行匿名pl/sql块。

 

Categories:

Tags:

No TrackBacks

TrackBack URL: http://dbsnake.com/cgi-bin/mt/mt-tb.cgi/4

Leave a comment