[MCOL-1193] Last Status Change of mysqld is not updated after Crash recovery Created: 2018-02-01  Updated: 2023-10-26  Resolved: 2019-07-10

Status: Closed
Project: MariaDB ColumnStore
Component/s: None
Affects Version/s: 1.1.2
Fix Version/s: Icebox

Type: Bug Priority: Minor
Reporter: Zdravelina Sokolovska (Inactive) Assignee: Unassigned
Resolution: Incomplete Votes: 0
Labels: None
Environment:

MCS run on VMs, Multi Server ColumnStore System UM1-PM1 ;guest OS RHEL 7.4


Issue Links:
Relates
relates to MCOL-1190 Process ID of mysqld is missed in the... Closed

 Description   

Last Status Change of mysqld is not updated after Crash recovery in the output of the command mcsadmin getsystemi

to recreate easily: just get Last Status Change of mysqld ,
then kill mysqld, verify that it recovered and check Last Status Change again

added logs from hostname.err file --those are seen the mysqld Status Change events and timestamps

1.mcsadmin getsystemi before crash

[root@um1 ~]#  mcsadmin getsystemi
 
 
 
WARNING: running on non Parent OAM Module, can't make configuration changes in this session.
 
         Access Console from 'pm1' if you need to make changes.
 
 
 
getsysteminfo   Thu Feb  1 17:56:07 2018
 
 
 
System cs-1.1.0
 
 
 
System and Module statuses
 
 
 
Component     Status                       Last Status Change
 
------------  --------------------------   ------------------------
 
System        ACTIVE                       Mon Jan 29 01:38:21 2018
 
 
 
Module um1    ACTIVE                       Mon Jan 29 01:38:19 2018
 
Module pm1    ACTIVE                       Mon Jan 29 01:38:09 2018
 
 
 
Active Parent OAM Performance Module is 'pm1'
 
MariaDB ColumnStore Replication Feature is enabled
 
 
 
 
 
MariaDB ColumnStore Process statuses
 
 
 
Process             Module    Status            Last Status Change        Process ID
 
------------------  ------    ---------------   ------------------------  ----------
 
ProcessMonitor      um1       ACTIVE            Mon Jan 29 01:37:54 2018        1020
 
ServerMonitor       um1       ACTIVE            Mon Jan 29 01:38:06 2018        1334
 
DBRMWorkerNode      um1       ACTIVE            Mon Jan 29 01:38:07 2018        1359
 
ExeMgr              um1       ACTIVE            Mon Jan 29 01:38:12 2018        1563
 
DDLProc             um1       ACTIVE            Mon Jan 29 01:38:16 2018        1574
 
DMLProc             um1       ACTIVE            Mon Jan 29 01:38:20 2018        1583
 
mysqld              um1       ACTIVE            Mon Jan 29 01:38:10 2018
 
 
 
ProcessMonitor      pm1       ACTIVE            Mon Jan 29 01:37:43 2018        1014
 
ProcessManager      pm1       ACTIVE            Mon Jan 29 01:37:49 2018        1128
 
DBRMControllerNode  pm1       ACTIVE            Mon Jan 29 01:38:01 2018        1384
 
ServerMonitor       pm1       ACTIVE            Mon Jan 29 01:38:03 2018        1400
 
DBRMWorkerNode      pm1       ACTIVE            Mon Jan 29 01:38:03 2018        1435
 
DecomSvr            pm1       ACTIVE            Mon Jan 29 01:38:07 2018        1549
 
PrimProc            pm1       ACTIVE            Mon Jan 29 01:38:09 2018        1602
 
WriteEngineServer   pm1       ACTIVE            Mon Jan 29 01:38:10 2018        1638
 
 
 
Active Alarm Counts: Critical = 0, Major = 0, Minor = 0, Warning = 0, Info = 0

mysqld recovered 

root@um1 ~]#  ps aux | grep mysql
 
root      1098  0.0  0.0 115396  1772 ?        S    Jan29   0:00 /bin/sh /usr/local/mariadb/columnstore/mysql//bin/mysqld_safe --datadir=/usr/local/mariadb/columnstore/mysql/db --pid-file=/usr/local/mariadb/columnstore/mysql/db/um1.xentio.lan.pid --ledir=/usr/local/mariadb/columnstore/mysql//bin
 
mysql    13440  0.0  0.2 2489672 173812 ?      Sl   16:29   0:02 /usr/local/mariadb/columnstore/mysql//bin/mysqld --basedir=/usr/local/mariadb/columnstore/mysql/ --datadir=/usr/local/mariadb/columnstore/mysql/db --plugin-dir=/usr/local/mariadb/columnstore/mysql/lib/plugin --user=mysql --log-error=/usr/local/mariadb/columnstore/mysql/db/um1.xentio.lan.err --pid-file=/usr/local/mariadb/columnstore/mysql/db/um1.xentio.lan.pid --socket=/usr/local/mariadb/columnstore/mysql/lib/mysql/mysql.sock --port=3306
 
root     13598  0.0  0.0 112660   972 pts/0    S+   17:57   0:00 grep --color=auto mysql
 
[root@um1 ~]# kill -9  13440
 
[root@um1 ~]#
 
[root@um1 ~]#
 
[root@um1 ~]#  ps aux | grep mysql
 
root      1098  0.0  0.0 115396  1772 ?        S    Jan29   0:00 /bin/sh /usr/local/mariadb/columnstore/mysql//bin/mysqld_safe --datadir=/usr/local/mariadb/columnstore/mysql/db --pid-file=/usr/local/mariadb/columnstore/mysql/db/um1.xentio.lan.pid --ledir=/usr/local/mariadb/columnstore/mysql//bin
 
mysql    13619  9.3  0.2 2423620 172340 ?      Sl   17:57   0:00 /usr/local/mariadb/columnstore/mysql//bin/mysqld --basedir=/usr/local/mariadb/columnstore/mysql/ --datadir=/usr/local/mariadb/columnstore/mysql/db --plugin-dir=/usr/local/mariadb/columnstore/mysql/lib/plugin --user=mysql --log-error=/usr/local/mariadb/columnstore/mysql/db/um1.xentio.lan.err --pid-file=/usr/local/mariadb/columnstore/mysql/db/um1.xentio.lan.pid --socket=/usr/local/mariadb/columnstore/mysql/lib/mysql/mysql.sock --port=3306
 
root     13654  0.0  0.0 112660   972 pts/0    S+   17:57   0:00 grep --color=auto mysql
 
[root@um1 ~]#

2. mcsadmin getsystemi after Crash recovery --Last Status Change of mysqld did not change

[root@um1 ~]#  mcsadmin getsystemi
 
 
 
WARNING: running on non Parent OAM Module, can't make configuration changes in this session.
 
         Access Console from 'pm1' if you need to make changes.
 
 
 
getsysteminfo   Thu Feb  1 17:57:46 2018
 
 
 
System cs-1.1.0
 
 
 
System and Module statuses
 
 
 
Component     Status                       Last Status Change
 
------------  --------------------------   ------------------------
 
System        ACTIVE                       Mon Jan 29 01:38:21 2018
 
 
 
Module um1    ACTIVE                       Mon Jan 29 01:38:19 2018
 
Module pm1    ACTIVE                       Mon Jan 29 01:38:09 2018
 
 
 
Active Parent OAM Performance Module is 'pm1'
 
MariaDB ColumnStore Replication Feature is enabled
 
 
 
 
 
MariaDB ColumnStore Process statuses
 
 
 
Process             Module    Status            Last Status Change        Process ID
 
------------------  ------    ---------------   ------------------------  ----------
 
ProcessMonitor      um1       ACTIVE            Mon Jan 29 01:37:54 2018        1020
 
ServerMonitor       um1       ACTIVE            Mon Jan 29 01:38:06 2018        1334
 
DBRMWorkerNode      um1       ACTIVE            Mon Jan 29 01:38:07 2018        1359
 
ExeMgr              um1       ACTIVE            Mon Jan 29 01:38:12 2018        1563
 
DDLProc             um1       ACTIVE            Mon Jan 29 01:38:16 2018        1574
 
DMLProc             um1       ACTIVE            Mon Jan 29 01:38:20 2018        1583
 
mysqld              um1       ACTIVE            Mon Jan 29 01:38:10 2018
 
 
 
ProcessMonitor      pm1       ACTIVE            Mon Jan 29 01:37:43 2018        1014
 
ProcessManager      pm1       ACTIVE            Mon Jan 29 01:37:49 2018        1128
 
DBRMControllerNode  pm1       ACTIVE            Mon Jan 29 01:38:01 2018        1384
 
ServerMonitor       pm1       ACTIVE            Mon Jan 29 01:38:03 2018        1400
 
DBRMWorkerNode      pm1       ACTIVE            Mon Jan 29 01:38:03 2018        1435
 
DecomSvr            pm1       ACTIVE            Mon Jan 29 01:38:07 2018        1549
 
PrimProc            pm1       ACTIVE            Mon Jan 29 01:38:09 2018        1602
 
WriteEngineServer   pm1       ACTIVE            Mon Jan 29 01:38:10 2018        1638
 
 
 
Active Alarm Counts: Critical = 0, Major = 0, Minor = 0, Warning = 0, Info = 0
 
[root@um1 ~]#
 
 

Node_Name.err logs :

180201 17:57:14 mysqld_safe Number of processes running now: 0
 
180201 17:57:14 mysqld_safe mysqld restarted
 
2018-02-01 17:57:14 140220162000960 [Note] /usr/local/mariadb/columnstore/mysql//bin/mysqld (mysqld 10.2.10-MariaDB-log) starting as process 13619 ...
 
180201 17:57:14 Columnstore: Started; Version: 1.0.2-1
 
180201 17:57:14 InfiniDB: Started; Version: 1.0.2-1
 
2018-02-01 17:57:14 140220162000960 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2018-02-01 17:57:14 140220162000960 [Note] InnoDB: Uses event mutexes
 
2018-02-01 17:57:14 140220162000960 [Note] InnoDB: Compressed tables use zlib 1.2.7
 
2018-02-01 17:57:14 140220162000960 [Note] InnoDB: Using Linux native AIO
 
2018-02-01 17:57:14 140220162000960 [Note] InnoDB: Number of pools: 1
 
2018-02-01 17:57:14 140220162000960 [Note] InnoDB: Using SSE2 crc32 instructions
 
2018-02-01 17:57:14 140220162000960 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
 
2018-02-01 17:57:14 140220162000960 [Note] InnoDB: Completed initialization of buffer pool
 
2018-02-01 17:57:14 140219083253504 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
 
2018-02-01 17:57:14 140220162000960 [Note] InnoDB: Highest supported file format is Barracuda.
 
2018-02-01 17:57:14 140220162000960 [Note] InnoDB: Starting crash recovery from checkpoint LSN=11236520
 
2018-02-01 17:57:14 140220162000960 [Note] InnoDB: Last binlog file '/usr/local/mariadb/columnstore/mysql/db/mysql-bin.000068', position 6413
 
2018-02-01 17:57:14 140220162000960 [Note] InnoDB: 128 out of 128 rollback segments are active.
 
2018-02-01 17:57:14 140220162000960 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
 
2018-02-01 17:57:14 140220162000960 [Note] InnoDB: Creating shared tablespace for temporary tables
 
2018-02-01 17:57:14 140220162000960 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
 
2018-02-01 17:57:14 140220162000960 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
 
2018-02-01 17:57:14 140220162000960 [Note] InnoDB: Waiting for purge to start
 
2018-02-01 17:57:14 140220162000960 [Note] InnoDB: 5.7.20 started; log sequence number 11236529
 
2018-02-01 17:57:14 140218845873920 [Note] InnoDB: Loading buffer pool(s) from /usr/local/mariadb/columnstore/mysql/db/ib_buffer_pool
 
2018-02-01 17:57:14 140218845873920 [Note] InnoDB: Buffer pool(s) load completed at 180201 17:57:14
 
2018-02-01 17:57:14 140220162000960 [Note] Plugin 'FEEDBACK' is disabled.
 
2018-02-01 17:57:14 140220162000960 [Note] Recovering after a crash using /usr/local/mariadb/columnstore/mysql/db/mysql-bin
 
2018-02-01 17:57:14 140220162000960 [Note] Starting crash recovery...
 
2018-02-01 17:57:14 140220162000960 [Note] Crash recovery finished.
 
2018-02-01 17:57:14 140220162000960 [Note] Server socket created on IP: '::'.
 
2018-02-01 17:57:14 140220162000960 [Note] Reading of all Master_info entries succeded
 
2018-02-01 17:57:14 140220162000960 [Note] Added new Master_info '' to hash table
 
2018-02-01 17:57:14 140220162000960 [Note] /usr/local/mariadb/columnstore/mysql//bin/mysqld: ready for connections.
 
Version: '10.2.10-MariaDB-log'  socket: '/usr/local/mariadb/columnstore/mysql/lib/mysql/mysql.sock'  port: 3306  Columnstore 1.1.2-1
 
[root@um1 ~]#



 Comments   
Comment by Andrew Hutchings (Inactive) [ 2019-07-10 ]

Might be fixed?

Generated at Thu Feb 08 02:26:54 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.