Sysadmin during upgrades / Sysadmin durante upgrades
Curious situation related to sysadmin during an upgrade (original version here: http://informix-technology.blogspot.com/2016/09/sysadmin-during-upgrades-sysadmin.html)
English version
Recently at a customer we were testing an upgrade from 11.50.xC7 to 12.10.xC7W1 and it apparently hanged. That's not what you like to see during an upgrade, even in a test environment.
We waited a few minutes and tried to understand what was happening. There was a thread called "convert" that apparently was idle. The thread stack trace apparently didn't change.
The functions showing up in the stack suggested it was trying to connect to a remote server following up what looks to be a call to UPDATE STATISTICS. That was a bit of a surprise.... looking at the online.log it was "hanged" during the "SCHAPI" phase. This is related to sysadmin.
Considering the upgrade didn't look good and it was a test system we decided to kill the engine and use onrestorept to revert back to version 11.50.
Then we decided to run an UPDATE STATISTICS FOR PROCEDURE on sysadmin database and voilá.... hanged again.
So, an UPDATE STATISTICS FOR PROCEDURE on sysadmin got hanged, and apparently that same thing happened during the upgrade. Further investigation led to a simple conclusion. We had created procedures in sysadmin to implement some monitoring tasks. And some of them tried to do remote operations on an engine where we centralize the monitoring data. Just before the upgrade a change was made to the instance $INFORMIXSQLHOSTS so that we "isolated" it from the outside world. This was done by adding some value to the service ports. The consequence of this was that during the upgrade, when it tried to run the UPDATE STATISTICS FOR PROCEDURE it tried to access a non-reachable remote engine. As it was not possible, it hanged some time for each remote instruction. Later tests on 12.10 showed the time it waits for each connection attempt is by default 60s and can be defined by changing the relatively new ONCONFIG parameter INFORMIXCONTIME
This can be easily reproduced. On a version 11.50 engine we create a simple (dumb) procedure:
bica@primary:informix-> onstat -
IBM Informix Dynamic Server Version 11.50.FC7 -- On-Line -- Up 00:30:33 -- 269068 Kbytes
bica@primary:informix-> cat test_remote_proc_stats.sql
CREATE PROCEDURE test_updstats_remote()
DEFINE i INTEGER;
SELECT 1 INTO i FROM stores@test:systables WHERE tabid = 1;
SELECT 2 INTO i FROM somedb@test:systables WHERE tabid = 1;
END PROCEDURE;
bica@primary:informix->
bica@primary:informix-> dbaccess sysadmin test_remote_proc_stats.sql
Database selected.
Routine created.
Database closed.
bica@primary:informix->
Database server "test" exists in the $INFORMIXSQLHOSTS, but points to a wrong port. Let's try an upgrade to 12.10.FC7 and see what happens.
From the online.log we get:
01:30:52 IBM Informix Dynamic Server Started.
01:30:52 Requested shared memory segment size rounded from 4308KB to 4796KB
Wed Aug 31 01:30:54 2016
01:30:54 Requested shared memory segment size rounded from 221001KB to 221004KB
01:30:54 Successfully added a bufferpool of page size 2K.
01:30:54 Event alarms enabled. ALARMPROG = '/usr/informix/srvr1210fc7w1/etc/alarmprogram.sh'
01:30:54 Booting Language
01:30:54 Loading Module
01:30:54 Booting Language
01:30:54 Loading Module
01:30:59 DR: DRAUTO is 0 (Off)
01:30:59 DR: ENCRYPT_HDR is 0 (HDR encryption Disabled)
01:30:59 Event notification facility epoll enabled.
01:31:00 Trusted host cache successfully built:/etc/hosts.equiv.
01:31:00 CCFLAGS2 value set to 0x200
01:31:00 SQL_FEAT_CTRL value set to 0x8008
01:31:00 SQL_DEF_CTRL value set to 0x4b0
01:31:00 IBM Informix Dynamic Server Version 12.10.FC7W1 Software Serial Number AAA#B000000
01:31:00 Conversion from version 11.50.xC6 Started
[...]
01:31:05 processing sysmaster
01:31:05 *** entity_ver=31 targetVersion=36 indexVersion= 0 ***
01:31:05 *** FromVersion=10 ToVersion=26 entity_ver=31 targetVersion=36 indexVersion=0 ***
01:31:05 *** FromVersion=26 ToVersion=28 entity_ver=31 targetVersion=36 indexVersion=1 ***
01:31:05 *** FromVersion=28 ToVersion=29 entity_ver=31 targetVersion=36 indexVersion=2 ***
01:31:05 *** FromVersion=29 ToVersion=30 entity_ver=31 targetVersion=36 indexVersion=3 ***
01:31:05 *** FromVersion=30 ToVersion=31 entity_ver=31 targetVersion=36 indexVersion=4 ***
01:31:05 *** FromVersion=31 ToVersion=32 entity_ver=31 targetVersion=36 indexVersion=5 ***
01:31:05 *** SQL 1 11.70.xC1 ***
01:31:05 Converting database sysmaster ...
01:31:06 The database sysmaster has been converted successfully.
01:31:06 *** FromVersion=32 ToVersion=33 entity_ver=32 targetVersion=36 indexVersion=6 ***
01:31:06 *** SQL 1 11.70.xC3 ***
01:31:06 Converting database sysmaster ...
01:31:06 The database sysmaster has been converted successfully.
01:31:06 *** FromVersion=33 ToVersion=34 entity_ver=33 targetVersion=36 indexVersion=7 ***
01:31:06 *** SQL 1 12.10.xC1 ***
01:31:06 Converting database sysmaster ...
01:31:06 The database sysmaster has been converted successfully.
01:31:06 *** FromVersion=34 ToVersion=35 entity_ver=34 targetVersion=36 indexVersion=8 ***
01:31:06 *** SQL 1 12.10.xC4 ***
01:31:06 Converting database sysmaster ...
01:31:06 The database sysmaster has been converted successfully.
01:31:06 *** FromVersion=35 ToVersion=36 entity_ver=35 targetVersion=36 indexVersion=9 ***
01:31:06 *** SQL 1 12.10.xC4 ***
01:31:06 processing sysutils
[...]
01:31:17 Conv/rev: calling conversion to 12.10.xC1 ...
01:31:19 Conv/rev: blade conversion to 12.10.xC1 completed
01:31:19 *** FromVersion=6 ToVersion=7 entity_ver=6 targetVersion=7 indexVersion=6 ***
01:31:19 *** BLADE 1 12.10.xC4 ***
01:31:19 Conv/rev: calling conversion to 12.10.xC4 ...
01:31:21 Conv/rev: blade conversion to 12.10.xC4 completed
01:31:21 Conv/rev: Finished conversion for component BLADE
01:31:21 Conv/rev: Started conversion for component SCHAPI
01:31:21 *** numVersions=7 targetVersion=7 ***
01:31:21 *** entity_ver=3 targetVersion=7 indexVersion= 0 ***
01:31:21 *** FromVersion=0 ToVersion=1 entity_ver=3 targetVersion=7 indexVersion=0 ***
01:31:21 *** FromVersion=1 ToVersion=2 entity_ver=3 targetVersion=7 indexVersion=1 ***
01:31:21 *** FromVersion=2 ToVersion=3 entity_ver=3 targetVersion=7 indexVersion=2 ***
01:31:21 *** FromVersion=3 ToVersion=4 entity_ver=3 targetVersion=7 indexVersion=3 ***
01:31:21 *** SCHAPI 1 11.70.xC1 ***
01:31:21 calling schapi_cvr1170_convert
01:31:21 *** FromVersion=4 ToVersion=5 entity_ver=4 targetVersion=7 indexVersion=4 ***
01:31:21 *** SCHAPI 1 11.70.xC3 ***
and it hangs...
Looking into the threads and thread stack:
IBM Informix Dynamic Server Version 12.10.FC7W1 -- Single-User -- Up 00:00:54 -- 266648 Kbytes
Threads:
tid tcb rstcb prty status vp-class name
2 4579d9e8 0 1 IO Idle 3lio* lio vp 0
3 458fd368 0 1 IO Idle 4pio* pio vp 0
4 4591e368 0 1 IO Idle 5aio* aio vp 0
5 4593f368 1d43600 1 IO Idle 6msc* msc vp 0
6 45970368 0 1 IO Idle 7fifo* fifo vp 0
7 45991608 44c1e028 3 sleeping secs: 1 1cpu main_loop()
8 459ed4c0 0 1 running 8soc* soctcppoll
9 459edc98 0 2 sleeping forever 1cpu* soctcplst
10 45a3cc88 44c1e8f0 1 sleeping secs: 1 1cpu flush_sub(0)
11 45a59028 44c1f1b8 1 sleeping secs: 1 1cpu flush_sub(1)
12 45a59368 44c1fa80 1 sleeping secs: 1 1cpu flush_sub(2)
13 45a596a8 44c20348 1 sleeping secs: 1 1cpu flush_sub(3)
14 45a599e8 44c20c10 1 sleeping secs: 1 1cpu flush_sub(4)
15 45a59d28 44c214d8 1 sleeping secs: 1 1cpu flush_sub(5)
16 45ab70e0 44c21da0 1 sleeping secs: 1 1cpu flush_sub(6)
17 45ab7420 44c22668 1 sleeping secs: 1 1cpu flush_sub(7)
18 45ab7760 0 3 IO Idle 1cpu* kaio
19 45c0c2c8 44c22f30 3 sleeping secs: 1 1cpu convert
20 45c0c9f8 44c237f8 2 sleeping secs: 1 1cpu aslogflush
21 45ccc958 44c240c0 1 sleeping secs: 8 1cpu btscanner_0
22 45ceba00 44c24988 3 cond wait ReadAhead 1cpu readahead_0
23 45d0eb50 44c25250 3 sleeping secs: 1 1cpu auto_tune
27 45d8aa80 44c25b18 1 sleeping secs: 0 1cpu sbspclean
28 45d30aa8 44c26ca8 1 sleeping secs: 1 1cpu defragclean
30 45d738f0 44c27570 3 sleeping secs: 1 1cpu* onmode_mon
31 45d89028 44c27e38 3 sleeping secs: 1 1cpu periodic
32 45d89608 44c28700 3 sleeping forever 1cpu memory
33 45d89be8 44c28fc8 3 sleeping secs: 15 1cpu session_mgr
35 45e08768 44c263e0 1 cond wait bp_cond 1cpu bf_priosweep()
IBM Informix Dynamic Server Version 12.10.FC7W1 -- Single-User -- Up 00:01:03 -- 266648 Kbytes
Stack for thread: 19 convert
base: 0x0000000045c19000
len: 69632
pc: 0x00000000013eaa6f
tos: 0x0000000045c24d50
state: sleeping
vp: 1
0x00000000013eaa6f (oninit) yield_processor_svp
0x00000000013ed5d3 (oninit) mt_yield
0x0000000001501340 (oninit) net_wait_for_connect
0x0000000001506ade (oninit) connsocket
0x000000000155f3c0 (oninit) tlConnect
0x000000000155c56a (oninit) slSQIreq
0x0000000001555343 (oninit) pfConReq
0x000000000154c628 (oninit) cmReqSync
0x000000000154d7ef (oninit) cmConReq
0x00000000014ee62e (oninit) ASF_Call
0x000000000076fd94 (oninit) dd_newconnect
0x00000000007712d0 (oninit) dd_remconnect
0x0000000000765404 (oninit) remcatalog
0x0000000000734831 (oninit) readtab
0x000000000073a372 (oninit) ddgettable_hierarchy_trace
0x00000000006bd1d5 (oninit) aud_ddgettable_trace
0x0000000000601206 (oninit) gettab_trace
0x0000000000655f15 (oninit) tlgetddtab_trace
0x0000000000656530 (oninit) tlp2tnode
0x000000000065af3b (oninit) tbl2tab
0x000000000063785d (oninit) sel2cb
0x0000000000639498 (oninit) subq2cb
0x00000000006632c1 (oninit) sq2expr
0x0000000000663373 (oninit) subq2expr
0x000000000066cca4 (oninit) expr2expr
0x0000000000682764 (oninit) ip_exprparse
0x00000000006a28fe (oninit) cmp_stmt
0x00000000006a2c1d (oninit) pr_compile
0x00000000006bf021 (oninit) aud_pr_compile
0x00000000006a3987 (oninit) updprocstat
0x00000000005cfba6 (oninit) excommand
0x0000000000f7eed7 (oninit) admin_exec_cmd
0x0000000000f7f2d5 (oninit) run_sql_script
0x0000000000f7f418 (oninit) run_script_etc
0x0000000000f9b826 (oninit) run_script_conv
0x0000000000f9b936 (oninit) ph_convrev
0x0000000000f42233 (oninit) schapi_cvr1170XC3_convert
0x0000000000f3f906 (oninit) do_each_version_work
0x0000000000f402d3 (oninit) generic_fw_main
0x0000000000f40cf6 (oninit) convertSM
0x00000000013c3720 (oninit) th_init_initgls
0x000000000142a518 (oninit) startup
The stack trace is clear. And precisely 2 minutes later it continues:
01:31:21 *** SCHAPI 1 11.70.xC3 ***
01:33:22 *** FromVersion=5 ToVersion=6 entity_ver=5 targetVersion=7 indexVersion=5 ***
01:33:22 *** SCHAPI 1 12.10.xC1 ***
01:33:22 calling schapi_cvr1210_convert
01:33:22 *** FromVersion=6 ToVersion=7 entity_ver=6 targetVersion=7 indexVersion=6 ***
01:33:22 *** SCHAPI 1 12.10.xC4 ***
01:33:22 calling schapi_cvr1210XC4_convert
01:33:23 Dynamically allocated new virtual shared memory segment (size 8192KB)
01:33:23 Memory sizes:resident:4796 KB, virtual:270044 KB, no SHMTOTAL limit
01:33:23 Conv/rev: Finished conversion for component SCHAPI
And it completed the conversion. In the customer situation, a later test showed a "hang" period of around 45m. So, a big warning.... The conversion process will run an UPDATE STATISTICS FOR PROCEDURE on sysadmin database. If you have created some procedures that do remote/distributed operations than you must consider this "problem" during the upgrade. Here are your options:
- Allow connections to that remote server(s)
- Remove the procedures and recreate them
- Use INFORMIXCONTIME parameter (12.10 only) to reduce the timeouts
- Remove the remote INFORMIXSERVER from the INFORMIXSQLHOSTS during migration. This also makes the connections attempts very quickly (as it simply can't find where to connect)
Versão Portuguesa
Há algum tempo num cliente, estando a testar uma migração de uma versão 11.50.FC7 para 12.10.FC7W1 deparámo-nos com um aparente bloqueio. Não é o que gostamos de ver, ainda que seja num ambiente de testes.
Esperámos uns minutos e tentámos perceber o que se estava a passar. Havia uma thread chamada "convert" que aparentemente estava inativa. O seu stack trace não parecia mudar
As funções que apareciam no stack sugeriam que estava a tentar contactar um servidor remoto, seguindo o que parecia ser uma chamada a um UPDATE STATISTICS. Isto foi uma grande surpresa.... Olhando para o online.log estava parado na fase "SCHAPI". Isto está relacionado com a sysadmin.
Considerando que o upgrade não estava com bom aspeto e que se tratava de um ambiente de testes decidimos abortar e usámos o onrestorept para reverter para a versão 11.50 (umas das minhas funcionalidades favoritas).
Para efeitos de teste e investigação decidimos executar um UPDATE STATISTICS FOR PROCEDURE na base de dados sysadmin. E voilá, preso de novo.
Portanto um UPDATE STATISTICS FOR PROCEDURE na sysadmin bloqueava o sistema e isso teria acontecido durante o upgrade. Após mais investigação concluímos que tínhamos criado procedimentos nesta base de dados para implementar algumas tarefas de monitorização e que esses procedimentos executavam algumas operações remotas para enviar a informação de monitorização para um sistema central. E antes do upgrade tinha sido feito uma alteração "de rotina" que consistiu na alteração do $INFORMIXSQLHOSTS de forma a "isolar" este motor. Basicamente foi adicionado um valor a todas as portas dos listeners, o que faz com que os clientes (não alterados) não consigam chegar ao ambiente. A consequência disto é que quando efetuamos o UPDATE STATISTICS este motor tenta aceder ao(s) motores referenciados nas operações remotas o que também não será possível. E como tal temos um timeout por cada operação remota encontrada nos procedimentos. Testes posteriores na 12.10 mostraram que a espera por cada tentativa de conexão é o valor por omissão (60s) ou o que estiver definido no parâmetro de $ONCONFIG INFORMIXCONTIME introduzido recentemente.
Tudo isto pode ser reproduzido facilmente. Num motor com a versão 11.50 criamos um procedimento simples (inútil):
bica@primary:informix-> onstat -
IBM Informix Dynamic Server Version 11.50.FC7 -- On-Line -- Up 00:30:33 -- 269068 Kbytes
CREATE PROCEDURE test_updstats_remote()
DEFINE i INTEGER;
SELECT 1 INTO i FROM stores@test:systables WHERE tabid = 1;
SELECT 2 INTO i FROM somedb@test:systables WHERE tabid = 1;
END PROCEDURE;
bica@primary:informix->
bica@primary:informix-> dbaccess sysadmin test_remote_proc_stats.sql
Database selected.
Routine created.
Database closed.
bica@primary:informix->O servidor de base de dados "test" existe no $INFORMIXSQLHOSTS, mas aponta para um serviço não existente. Tentemos um upgrade para a 12.10.FC7 e vejamos o que acontece:
No online.log temos:
01:30:52 IBM Informix Dynamic Server Started.
01:30:52 Requested shared memory segment size rounded from 4308KB to 4796KB
Wed Aug 31 01:30:54 2016
01:30:54 Requested shared memory segment size rounded from 221001KB to 221004KB
01:30:54 Successfully added a bufferpool of page size 2K.
01:30:54 Event alarms enabled. ALARMPROG = '/usr/informix/srvr1210fc7w1/etc/alarmprogram.sh'
01:30:54 Booting Language from module <>
01:30:54 Loading Module
01:30:54 Booting Language from module <>
01:30:54 Loading Module
01:30:59 DR: DRAUTO is 0 (Off)
01:30:59 DR: ENCRYPT_HDR is 0 (HDR encryption Disabled)
01:30:59 Event notification facility epoll enabled.
01:31:00 Trusted host cache successfully built:/etc/hosts.equiv.
01:31:00 CCFLAGS2 value set to 0x200
01:31:00 SQL_FEAT_CTRL value set to 0x8008
01:31:00 SQL_DEF_CTRL value set to 0x4b0
01:31:00 IBM Informix Dynamic Server Version 12.10.FC7W1 Software Serial Number AAA#B000000
01:31:00 Conversion from version 11.50.xC6 Started
[...]
01:31:05 processing sysmaster
01:31:05 *** entity_ver=31 targetVersion=36 indexVersion= 0 ***
01:31:05 *** FromVersion=10 ToVersion=26 entity_ver=31 targetVersion=36 indexVersion=0 ***
01:31:05 *** FromVersion=26 ToVersion=28 entity_ver=31 targetVersion=36 indexVersion=1 ***
01:31:05 *** FromVersion=28 ToVersion=29 entity_ver=31 targetVersion=36 indexVersion=2 ***
01:31:05 *** FromVersion=29 ToVersion=30 entity_ver=31 targetVersion=36 indexVersion=3 ***
01:31:05 *** FromVersion=30 ToVersion=31 entity_ver=31 targetVersion=36 indexVersion=4 ***
01:31:05 *** FromVersion=31 ToVersion=32 entity_ver=31 targetVersion=36 indexVersion=5 ***
01:31:05 *** SQL 1 11.70.xC1 ***
01:31:05 Converting database sysmaster ...
01:31:06 The database sysmaster has been converted successfully.
01:31:06 *** FromVersion=32 ToVersion=33 entity_ver=32 targetVersion=36 indexVersion=6 ***
01:31:06 *** SQL 1 11.70.xC3 ***
01:31:06 Converting database sysmaster ...
01:31:06 The database sysmaster has been converted successfully.
01:31:06 *** FromVersion=33 ToVersion=34 entity_ver=33 targetVersion=36 indexVersion=7 ***
01:31:06 *** SQL 1 12.10.xC1 ***
01:31:06 Converting database sysmaster ...
01:31:06 The database sysmaster has been converted successfully.
01:31:06 *** FromVersion=34 ToVersion=35 entity_ver=34 targetVersion=36 indexVersion=8 ***
01:31:06 *** SQL 1 12.10.xC4 ***
01:31:06 Converting database sysmaster ...
01:31:06 The database sysmaster has been converted successfully.
01:31:06 *** FromVersion=35 ToVersion=36 entity_ver=35 targetVersion=36 indexVersion=9 ***
01:31:06 *** SQL 1 12.10.xC4 ***
01:31:06 processing sysutils
[...]
01:31:17 Conv/rev: calling conversion to 12.10.xC1 ...
01:31:19 Conv/rev: blade conversion to 12.10.xC1 completed
01:31:19 *** FromVersion=6 ToVersion=7 entity_ver=6 targetVersion=7 indexVersion=6 ***
01:31:19 *** BLADE 1 12.10.xC4 ***
01:31:19 Conv/rev: calling conversion to 12.10.xC4 ...
01:31:21 Conv/rev: blade conversion to 12.10.xC4 completed
01:31:21 Conv/rev: Finished conversion for component BLADE
01:31:21 Conv/rev: Started conversion for component SCHAPI
01:31:21 *** numVersions=7 targetVersion=7 ***
01:31:21 *** entity_ver=3 targetVersion=7 indexVersion= 0 ***
01:31:21 *** FromVersion=0 ToVersion=1 entity_ver=3 targetVersion=7 indexVersion=0 ***
01:31:21 *** FromVersion=1 ToVersion=2 entity_ver=3 targetVersion=7 indexVersion=1 ***
01:31:21 *** FromVersion=2 ToVersion=3 entity_ver=3 targetVersion=7 indexVersion=2 ***
01:31:21 *** FromVersion=3 ToVersion=4 entity_ver=3 targetVersion=7 indexVersion=3 ***
01:31:21 *** SCHAPI 1 11.70.xC1 ***
01:31:21 calling schapi_cvr1170_convert
01:31:21 *** FromVersion=4 ToVersion=5 entity_ver=4 targetVersion=7 indexVersion=4 ***
01:31:21 *** SCHAPI 1 11.70.xC3 ***
e bloqueia...
Vejamos as threads e o respetivo stack:
IBM Informix Dynamic Server Version 12.10.FC7W1 -- Single-User -- Up 00:00:54 -- 266648 Kbytes
Threads:
tid tcb rstcb prty status vp-class name
2 4579d9e8 0 1 IO Idle 3lio* lio vp 0
3 458fd368 0 1 IO Idle 4pio* pio vp 0
4 4591e368 0 1 IO Idle 5aio* aio vp 0
5 4593f368 1d43600 1 IO Idle 6msc* msc vp 0
6 45970368 0 1 IO Idle 7fifo* fifo vp 0
7 45991608 44c1e028 3 sleeping secs: 1 1cpu main_loop()
8 459ed4c0 0 1 running 8soc* soctcppoll
9 459edc98 0 2 sleeping forever 1cpu* soctcplst
10 45a3cc88 44c1e8f0 1 sleeping secs: 1 1cpu flush_sub(0)
11 45a59028 44c1f1b8 1 sleeping secs: 1 1cpu flush_sub(1)
12 45a59368 44c1fa80 1 sleeping secs: 1 1cpu flush_sub(2)
13 45a596a8 44c20348 1 sleeping secs: 1 1cpu flush_sub(3)
14 45a599e8 44c20c10 1 sleeping secs: 1 1cpu flush_sub(4)
15 45a59d28 44c214d8 1 sleeping secs: 1 1cpu flush_sub(5)
16 45ab70e0 44c21da0 1 sleeping secs: 1 1cpu flush_sub(6)
17 45ab7420 44c22668 1 sleeping secs: 1 1cpu flush_sub(7)
18 45ab7760 0 3 IO Idle 1cpu* kaio
19 45c0c2c8 44c22f30 3 sleeping secs: 1 1cpu convert
20 45c0c9f8 44c237f8 2 sleeping secs: 1 1cpu aslogflush
21 45ccc958 44c240c0 1 sleeping secs: 8 1cpu btscanner_0
22 45ceba00 44c24988 3 cond wait ReadAhead 1cpu readahead_0
23 45d0eb50 44c25250 3 sleeping secs: 1 1cpu auto_tune
27 45d8aa80 44c25b18 1 sleeping secs: 0 1cpu sbspclean
28 45d30aa8 44c26ca8 1 sleeping secs: 1 1cpu defragclean
30 45d738f0 44c27570 3 sleeping secs: 1 1cpu* onmode_mon
31 45d89028 44c27e38 3 sleeping secs: 1 1cpu periodic
32 45d89608 44c28700 3 sleeping forever 1cpu memory
33 45d89be8 44c28fc8 3 sleeping secs: 15 1cpu session_mgr
35 45e08768 44c263e0 1 cond wait bp_cond 1cpu bf_priosweep()
IBM Informix Dynamic Server Version 12.10.FC7W1 -- Single-User -- Up 00:01:03 -- 266648 Kbytes
Stack for thread: 19 convert
base: 0x0000000045c19000
len: 69632
pc: 0x00000000013eaa6f
tos: 0x0000000045c24d50
state: sleeping
vp: 1
0x00000000013eaa6f (oninit) yield_processor_svp
0x00000000013ed5d3 (oninit) mt_yield
0x0000000001501340 (oninit) net_wait_for_connect
0x0000000001506ade (oninit) connsocket
0x000000000155f3c0 (oninit) tlConnect
0x000000000155c56a (oninit) slSQIreq
0x0000000001555343 (oninit) pfConReq
0x000000000154c628 (oninit) cmReqSync
0x000000000154d7ef (oninit) cmConReq
0x00000000014ee62e (oninit) ASF_Call
0x000000000076fd94 (oninit) dd_newconnect
0x00000000007712d0 (oninit) dd_remconnect
0x0000000000765404 (oninit) remcatalog
0x0000000000734831 (oninit) readtab
0x000000000073a372 (oninit) ddgettable_hierarchy_trace
0x00000000006bd1d5 (oninit) aud_ddgettable_trace
0x0000000000601206 (oninit) gettab_trace
0x0000000000655f15 (oninit) tlgetddtab_trace
0x0000000000656530 (oninit) tlp2tnode
0x000000000065af3b (oninit) tbl2tab
0x000000000063785d (oninit) sel2cb
0x0000000000639498 (oninit) subq2cb
0x00000000006632c1 (oninit) sq2expr
0x0000000000663373 (oninit) subq2expr
0x000000000066cca4 (oninit) expr2expr
0x0000000000682764 (oninit) ip_exprparse
0x00000000006a28fe (oninit) cmp_stmt
0x00000000006a2c1d (oninit) pr_compile
0x00000000006bf021 (oninit) aud_pr_compile
0x00000000006a3987 (oninit) updprocstat
0x00000000005cfba6 (oninit) excommand
0x0000000000f7eed7 (oninit) admin_exec_cmd
0x0000000000f7f2d5 (oninit) run_sql_script
0x0000000000f7f418 (oninit) run_script_etc
0x0000000000f9b826 (oninit) run_script_conv
0x0000000000f9b936 (oninit) ph_convrev
0x0000000000f42233 (oninit) schapi_cvr1170XC3_convert
0x0000000000f3f906 (oninit) do_each_version_work
0x0000000000f402d3 (oninit) generic_fw_main
0x0000000000f40cf6 (oninit) convertSM
0x00000000013c3720 (oninit) th_init_initgls
0x000000000142a518 (oninit) startup
O stack é claro. E precisamente 2 minutos depois a conversão continua (o procedimento tinha duas instruções remotas):
01:31:21 *** SCHAPI 1 11.70.xC3 ***
01:33:22 *** FromVersion=5 ToVersion=6 entity_ver=5 targetVersion=7 indexVersion=5 ***
01:33:22 *** SCHAPI 1 12.10.xC1 ***
01:33:22 calling schapi_cvr1210_convert
01:33:22 *** FromVersion=6 ToVersion=7 entity_ver=6 targetVersion=7 indexVersion=6 ***
01:33:22 *** SCHAPI 1 12.10.xC4 ***
01:33:22 calling schapi_cvr1210XC4_convert
01:33:23 Dynamically allocated new virtual shared memory segment (size 8192KB)
01:33:23 Memory sizes:resident:4796 KB, virtual:270044 KB, no SHMTOTAL limit
01:33:23 Conv/rev: Finished conversion for component SCHAPI
E termina a conversão. Na situação concreta do cliente, um novo teste com a mesma instância apresentou um "bloqueio" durante cerca de 45m (correspondente a sensivelmente o mesmo número de instruções remotas nos procedimentos da sysadmin). Portanto um grande alerta...: O processo de conversão irá executar um UPDATE STATISTICS FOR PROCEDURE na base de dados sysadmin (isto não está documentado, mas é natural tendo em conta o processo de conversão da mesma). Se porventura criou procedimentos que acedem a instâncias remotas, então deverá ter isto em conta As opções para lidar com isto serão::
- Permitir as ligações ao(s) servidor remoto
- Remover os procedimentos e recriá-los depois da migração
- Usar o parâmetro INFORMIXCONTIME (a partir da 12.10) para reduzir os tempos de espera
- Remover o INFORMIXSERVER remoto do $INFORMIXSQLHOSTS durante a conversão. Isto também permite acelerar as tentativas de conexão pois ao não encontrar a referência no ficheiro o motor não sabe onde se ligar, e portanto não se aplicam os timeouts
Posts
No comments:
Post a Comment