Here is the steps troubleshoot for Netezza database down issue
1.look for the contents of sysmgr.log under/nz/kit/log/sysmgr
2.look for the content of the pg.log under /nz/ki/log/postgres/
3.grep the timeline of the DB down from the pg.log
nz@<server_name>:/export/home/nz> grep -i "shut down" /nz/kit/log/postgres/pg.log.1
2018-06-05 05:07:16.858990 EDT [30134] NOTICE: database system was shut down at 2018-06-05 05:07:16 EDT
2018-06-05 14:00:39.323065 EDT [1983] NOTICE: database system was shut down at 2018-06-05 14:00:39 EDT
2018-06-05 16:29:28.631563 EDT [17920] NOTICE: database system was shut down at 2018-06-05 16:29:28 EDT
2018-06-05 17:21:01.303872 EDT [27842] NOTICE: database system was shut down at 2018-06-05 17:21:01 EDT
2018-06-05 18:35:51.314193 EDT [2921] NOTICE: database system was shut down at 2018-06-05 18:35:51 EDT
4.look for the core files and convert the core files to readable format.
456 2018-06-05 23:56:17 nzgdb -core /nz/data/base/1/core.1528233612.21424 -bt > 21424.bt
457 2018-06-05 23:56:51 nzgdb -core /nz/data/base/1/core.1528230523.11816 -bt > 11816.bt
458 2018-06-05 23:57:29 nzgdb -core /nz/data/base/1/core.1528221590.28144 -bt > 28144.bt
459 2018-06-05 23:58:03 nzgdb -core /nz/data/base/1/core.1528189585.23904 -bt > 23904.bt
460 2018-06-05 23:58:46 nzgdb -core /nz/data/base/1/core.1528185575.5528 -bt > 5528.bt
5.grep the PID with pg.log find out what went wrong on the system during the core dump generated time.
466 2018-06-06 00:05:22 grep '\[27208\]' /nz/kit/log/postgres/pg.log
467 2018-06-06 00:09:44 2018-06-05 18:34:36.874070 EDT [27208] DEBUG: connection: host=10.128.72.44 user=NZKOMUSER database=CVKOMNZP remotepid=5177762 fetype=1
468 2018-06-06 00:09:44 2018-06-05 18:34:36.874088 EDT [27208] DEBUG: Session id is 16279
469 2018-06-06 00:09:44 2018-06-05 18:34:36.877957 EDT [27208] DEBUG: QUERY: select current_catalog, current_user
470 2018-06-06 00:09:44 2018-06-05 18:34:36.879496 EDT [27208] DEBUG: QUERY: exec dta_box_inv_hist_incr_load(' TARGET_TABLE==DTA_STG_nz_tbl_HISTORY><TARGET_FINAL_TABLE==nz_tbl_HISTORY><SRC_LAST_MODIFIED_DATE_COL==dtm_last_updated><SRC_PULL_DATE_COL==BOXINVTRY_ID><SRC_PARALLEL_TASK_COL==><SOURCE_TABLE==nz_tbl_HISTORY><SOURCE_SCHEMA==KOMUSER><SOURCE_FILTER==><SRC_PK_COL==BOXINVTRY_ID><DTA_JOB_ID==503><TPPIL_KLMDATE==04-jun-2018 06:49:29 AM ')
471 2018-06-06 00:09:44 2018-06-05 18:34:36.897353 EDT [27208] DEBUG: UpdateStatsInsertDummy called on table 'TEMPFUNC13279476'
472 2018-06-06 00:09:44 2018-06-05 18:34:36.906701 EDT [27208] DEBUG: STORED PROCEDURE EXEC: SELECT dta_nz_parse_parameter_str(ltrim( $1 )) - Variables ( TARGET_TABLE==DTA_STG_nz_tbl_HISTORY><TARGET_FINAL_TABLE==nz_tbl_HISTORY><SRC_LAST_MODIFIED_DATE_COL==dtm_last_updated><SRC_PULL_DATE_COL==BOXINVTRY_ID><SRC_PARALLEL_TASK_COL==><SOURCE_TABLE==nz_tbl_HISTORY><SOURCE_SCHEMA==KOMUSER><SOURCE_FILTER==><SRC_PK_COL==BOXINVTRY_ID><DTA_JOB_ID==503><TPPIL_KLMDATE==04-jun-2018 06:49:29 AM )
473 2018-06-06 00:09:44 2018-06-05 18:34:36.914496 EDT [27208] DEBUG: STORED PROCEDURE EXEC: SELECT * from table(REGEXP_SPLIT_ROWS( $1 ,'><')) - Variables (TARGET_TABLE==DTA_STG_nz_tbl_HISTORY><TARGET_FINAL_TABLE==nz_tbl_HISTORY><SRC_LAST_MODIFIED_DATE_COL==dtm_last_updated><SRC_PULL_DATE_COL==BOXINVTRY_ID><SRC_PARALLEL_TASK_COL==><SOURCE_TABLE==nz_tbl_HISTORY><SOURCE_SCHEMA==KOMUSER><SOURCE_FILTER==><SRC_PK_COL==BOXINVTRY_ID><DTA_JOB_ID==503><TPPIL_KLMDATE==04-jun-2018 06:49:29 AM )
474 2018-06-06 00:09:44 2018-06-05 18:34:36.927852 EDT [27208] DEBUG: STORED PROCEDURE EXEC: insert into TEMPFUNC13279476 values( 'TARGET_TABLE','DTA_STG_nz_tbl_HISTORY')
475 2018-06-06 00:09:44 2018-06-05 18:34:41.076371 EDT [27208] DEBUG: 1 rows inserted
476 2018-06-06 00:09:44 2018-06-05 18:34:41.084061 EDT [27208] DEBUG: STORED PROCEDURE EXEC: insert into TEMPFUNC13279476 values( 'TARGET_FINAL_TABLE','nz_tbl_HISTORY')
477 2018-06-06 00:09:44 2018-06-05 18:34:44.982932 EDT [27208] DEBUG: 1 rows inserted
478 2018-06-06 00:09:44 2018-06-05 18:34:44.990653 EDT [27208] DEBUG: STORED PROCEDURE EXEC: insert into TEMPFUNC13279476 values( 'SRC_LAST_MODIFIED_DATE_COL','dtm_last_updated')
479 2018-06-06 00:09:44 2018-06-05 18:34:47.670894 EDT [27208] DEBUG: 1 rows inserted
480 2018-06-06 00:09:44 2018-06-05 18:34:47.678735 EDT [27208] DEBUG: STORED PROCEDURE EXEC: insert into TEMPFUNC13279476 values( 'SRC_PULL_DATE_COL','BOXINVTRY_ID')
481 2018-06-06 00:09:44 2018-06-05 18:34:52.229912 EDT [27208] DEBUG: 1 rows inserted
482 2018-06-06 00:09:44 2018-06-05 18:34:52.237441 EDT [27208] DEBUG: STORED PROCEDURE EXEC: insert into TEMPFUNC13279476 values( 'SRC_PARALLEL_TASK_COL','')
483 2018-06-06 00:09:44 2018-06-05 18:34:53.913637 EDT [27208] DEBUG: 1 rows inserted
484 2018-06-06 00:09:44 2018-06-05 18:34:53.926314 EDT [27208] DEBUG: STORED PROCEDURE EXEC: insert into TEMPFUNC13279476 values( 'SOURCE_TABLE','nz_tbl_HISTORY')
485 2018-06-06 00:09:44 2018-06-05 18:34:55.508722 EDT [27208] DEBUG: 1 rows inserted
486 2018-06-06 00:09:44 2018-06-05 18:34:55.518331 EDT [27208] DEBUG: STORED PROCEDURE EXEC: insert into TEMPFUNC13279476 values( 'SOURCE_SCHEMA','KOMUSER')
487 2018-06-06 00:09:44 2018-06-05 18:34:56.975557 EDT [27208] DEBUG: 1 rows inserted
488 2018-06-06 00:09:44 2018-06-05 18:34:56.983190 EDT [27208] DEBUG: STORED PROCEDURE EXEC: insert into TEMPFUNC13279476 values( 'SOURCE_FILTER','')
489 2018-06-06 00:09:44 2018-06-05 18:34:59.367628 EDT [27208] DEBUG: 1 rows inserted
490 2018-06-06 00:09:44 2018-06-05 18:34:59.375228 EDT [27208] DEBUG: STORED PROCEDURE EXEC: insert into TEMPFUNC13279476 values( 'SRC_PK_COL','BOXINVTRY_ID')
491 2018-06-06 00:09:44 2018-06-05 18:35:00.948244 EDT [27208] DEBUG: 1 rows inserted
492 2018-06-06 00:09:44 2018-06-05 18:35:00.955864 EDT [27208] DEBUG: STORED PROCEDURE EXEC: insert into TEMPFUNC13279476 values( 'DTA_JOB_ID','503')
493 2018-06-06 00:09:44 2018-06-05 18:35:04.072782 EDT [27208] DEBUG: 1 rows inserted
494 2018-06-06 00:09:44 2018-06-05 18:35:04.080479 EDT [27208] DEBUG: STORED PROCEDURE EXEC: insert into TEMPFUNC13279476 values( 'TPPIL_KLMDATE','04-jun-2018 06:49:29 AM ')
495 2018-06-06 00:09:44 2018-06-05 18:35:06.168680 EDT [27208] DEBUG: 1 rows inserted
496 2018-06-06 00:09:44 2018-06-05 18:35:06.401591 EDT [27208] DEBUG: STORED PROCEDURE EXEC: delete from nz_tbl_
we had checked all the coredump generated during the time all the time NPS executing the same query and crashing the NPS and finally we asked user to stop executing the query and later IBM found that it was bug on the 7.0 version system
work around for this bug:
1)upgrade the NPS to recent version
2)clean the versioning of the table
we cleared the version of the table and NPs stable after that.
1.look for the contents of sysmgr.log under/nz/kit/log/sysmgr
2.look for the content of the pg.log under /nz/ki/log/postgres/
3.grep the timeline of the DB down from the pg.log
nz@<server_name>:/export/home/nz> grep -i "shut down" /nz/kit/log/postgres/pg.log.1
2018-06-05 05:07:16.858990 EDT [30134] NOTICE: database system was shut down at 2018-06-05 05:07:16 EDT
2018-06-05 14:00:39.323065 EDT [1983] NOTICE: database system was shut down at 2018-06-05 14:00:39 EDT
2018-06-05 16:29:28.631563 EDT [17920] NOTICE: database system was shut down at 2018-06-05 16:29:28 EDT
2018-06-05 17:21:01.303872 EDT [27842] NOTICE: database system was shut down at 2018-06-05 17:21:01 EDT
2018-06-05 18:35:51.314193 EDT [2921] NOTICE: database system was shut down at 2018-06-05 18:35:51 EDT
4.look for the core files and convert the core files to readable format.
456 2018-06-05 23:56:17 nzgdb -core /nz/data/base/1/core.1528233612.21424 -bt > 21424.bt
457 2018-06-05 23:56:51 nzgdb -core /nz/data/base/1/core.1528230523.11816 -bt > 11816.bt
458 2018-06-05 23:57:29 nzgdb -core /nz/data/base/1/core.1528221590.28144 -bt > 28144.bt
459 2018-06-05 23:58:03 nzgdb -core /nz/data/base/1/core.1528189585.23904 -bt > 23904.bt
460 2018-06-05 23:58:46 nzgdb -core /nz/data/base/1/core.1528185575.5528 -bt > 5528.bt
5.grep the PID with pg.log find out what went wrong on the system during the core dump generated time.
466 2018-06-06 00:05:22 grep '\[27208\]' /nz/kit/log/postgres/pg.log
467 2018-06-06 00:09:44 2018-06-05 18:34:36.874070 EDT [27208] DEBUG: connection: host=10.128.72.44 user=NZKOMUSER database=CVKOMNZP remotepid=5177762 fetype=1
468 2018-06-06 00:09:44 2018-06-05 18:34:36.874088 EDT [27208] DEBUG: Session id is 16279
469 2018-06-06 00:09:44 2018-06-05 18:34:36.877957 EDT [27208] DEBUG: QUERY: select current_catalog, current_user
470 2018-06-06 00:09:44 2018-06-05 18:34:36.879496 EDT [27208] DEBUG: QUERY: exec dta_box_inv_hist_incr_load(' TARGET_TABLE==DTA_STG_nz_tbl_HISTORY><TARGET_FINAL_TABLE==nz_tbl_HISTORY><SRC_LAST_MODIFIED_DATE_COL==dtm_last_updated><SRC_PULL_DATE_COL==BOXINVTRY_ID><SRC_PARALLEL_TASK_COL==><SOURCE_TABLE==nz_tbl_HISTORY><SOURCE_SCHEMA==KOMUSER><SOURCE_FILTER==><SRC_PK_COL==BOXINVTRY_ID><DTA_JOB_ID==503><TPPIL_KLMDATE==04-jun-2018 06:49:29 AM ')
471 2018-06-06 00:09:44 2018-06-05 18:34:36.897353 EDT [27208] DEBUG: UpdateStatsInsertDummy called on table 'TEMPFUNC13279476'
472 2018-06-06 00:09:44 2018-06-05 18:34:36.906701 EDT [27208] DEBUG: STORED PROCEDURE EXEC: SELECT dta_nz_parse_parameter_str(ltrim( $1 )) - Variables ( TARGET_TABLE==DTA_STG_nz_tbl_HISTORY><TARGET_FINAL_TABLE==nz_tbl_HISTORY><SRC_LAST_MODIFIED_DATE_COL==dtm_last_updated><SRC_PULL_DATE_COL==BOXINVTRY_ID><SRC_PARALLEL_TASK_COL==><SOURCE_TABLE==nz_tbl_HISTORY><SOURCE_SCHEMA==KOMUSER><SOURCE_FILTER==><SRC_PK_COL==BOXINVTRY_ID><DTA_JOB_ID==503><TPPIL_KLMDATE==04-jun-2018 06:49:29 AM )
473 2018-06-06 00:09:44 2018-06-05 18:34:36.914496 EDT [27208] DEBUG: STORED PROCEDURE EXEC: SELECT * from table(REGEXP_SPLIT_ROWS( $1 ,'><')) - Variables (TARGET_TABLE==DTA_STG_nz_tbl_HISTORY><TARGET_FINAL_TABLE==nz_tbl_HISTORY><SRC_LAST_MODIFIED_DATE_COL==dtm_last_updated><SRC_PULL_DATE_COL==BOXINVTRY_ID><SRC_PARALLEL_TASK_COL==><SOURCE_TABLE==nz_tbl_HISTORY><SOURCE_SCHEMA==KOMUSER><SOURCE_FILTER==><SRC_PK_COL==BOXINVTRY_ID><DTA_JOB_ID==503><TPPIL_KLMDATE==04-jun-2018 06:49:29 AM )
474 2018-06-06 00:09:44 2018-06-05 18:34:36.927852 EDT [27208] DEBUG: STORED PROCEDURE EXEC: insert into TEMPFUNC13279476 values( 'TARGET_TABLE','DTA_STG_nz_tbl_HISTORY')
475 2018-06-06 00:09:44 2018-06-05 18:34:41.076371 EDT [27208] DEBUG: 1 rows inserted
476 2018-06-06 00:09:44 2018-06-05 18:34:41.084061 EDT [27208] DEBUG: STORED PROCEDURE EXEC: insert into TEMPFUNC13279476 values( 'TARGET_FINAL_TABLE','nz_tbl_HISTORY')
477 2018-06-06 00:09:44 2018-06-05 18:34:44.982932 EDT [27208] DEBUG: 1 rows inserted
478 2018-06-06 00:09:44 2018-06-05 18:34:44.990653 EDT [27208] DEBUG: STORED PROCEDURE EXEC: insert into TEMPFUNC13279476 values( 'SRC_LAST_MODIFIED_DATE_COL','dtm_last_updated')
479 2018-06-06 00:09:44 2018-06-05 18:34:47.670894 EDT [27208] DEBUG: 1 rows inserted
480 2018-06-06 00:09:44 2018-06-05 18:34:47.678735 EDT [27208] DEBUG: STORED PROCEDURE EXEC: insert into TEMPFUNC13279476 values( 'SRC_PULL_DATE_COL','BOXINVTRY_ID')
481 2018-06-06 00:09:44 2018-06-05 18:34:52.229912 EDT [27208] DEBUG: 1 rows inserted
482 2018-06-06 00:09:44 2018-06-05 18:34:52.237441 EDT [27208] DEBUG: STORED PROCEDURE EXEC: insert into TEMPFUNC13279476 values( 'SRC_PARALLEL_TASK_COL','')
483 2018-06-06 00:09:44 2018-06-05 18:34:53.913637 EDT [27208] DEBUG: 1 rows inserted
484 2018-06-06 00:09:44 2018-06-05 18:34:53.926314 EDT [27208] DEBUG: STORED PROCEDURE EXEC: insert into TEMPFUNC13279476 values( 'SOURCE_TABLE','nz_tbl_HISTORY')
485 2018-06-06 00:09:44 2018-06-05 18:34:55.508722 EDT [27208] DEBUG: 1 rows inserted
486 2018-06-06 00:09:44 2018-06-05 18:34:55.518331 EDT [27208] DEBUG: STORED PROCEDURE EXEC: insert into TEMPFUNC13279476 values( 'SOURCE_SCHEMA','KOMUSER')
487 2018-06-06 00:09:44 2018-06-05 18:34:56.975557 EDT [27208] DEBUG: 1 rows inserted
488 2018-06-06 00:09:44 2018-06-05 18:34:56.983190 EDT [27208] DEBUG: STORED PROCEDURE EXEC: insert into TEMPFUNC13279476 values( 'SOURCE_FILTER','')
489 2018-06-06 00:09:44 2018-06-05 18:34:59.367628 EDT [27208] DEBUG: 1 rows inserted
490 2018-06-06 00:09:44 2018-06-05 18:34:59.375228 EDT [27208] DEBUG: STORED PROCEDURE EXEC: insert into TEMPFUNC13279476 values( 'SRC_PK_COL','BOXINVTRY_ID')
491 2018-06-06 00:09:44 2018-06-05 18:35:00.948244 EDT [27208] DEBUG: 1 rows inserted
492 2018-06-06 00:09:44 2018-06-05 18:35:00.955864 EDT [27208] DEBUG: STORED PROCEDURE EXEC: insert into TEMPFUNC13279476 values( 'DTA_JOB_ID','503')
493 2018-06-06 00:09:44 2018-06-05 18:35:04.072782 EDT [27208] DEBUG: 1 rows inserted
494 2018-06-06 00:09:44 2018-06-05 18:35:04.080479 EDT [27208] DEBUG: STORED PROCEDURE EXEC: insert into TEMPFUNC13279476 values( 'TPPIL_KLMDATE','04-jun-2018 06:49:29 AM ')
495 2018-06-06 00:09:44 2018-06-05 18:35:06.168680 EDT [27208] DEBUG: 1 rows inserted
496 2018-06-06 00:09:44 2018-06-05 18:35:06.401591 EDT [27208] DEBUG: STORED PROCEDURE EXEC: delete from nz_tbl_
we had checked all the coredump generated during the time all the time NPS executing the same query and crashing the NPS and finally we asked user to stop executing the query and later IBM found that it was bug on the 7.0 version system
work around for this bug:
1)upgrade the NPS to recent version
2)clean the versioning of the table
we cleared the version of the table and NPs stable after that.
No comments:
Post a Comment