Pentaho PDI logging: fixing concurrency issues

If you are running single thread logging for PDI transformation to database you are good.
I am using MySQL (Percona cluster)
I got multiple  issues with concurrent inserts/updates to this table:

ERROR (version 8.2.0.0-342, build 8.2.0.0-342 from 2018-11-14 10.30.55 by buildguy) : Unable to write log record to log table
or
Deadlock found when trying to get lock; try restarting transaction

What major issues with DB schema I see:
1) ID_BATCH  column is generated on Pentaho side, it locks tables "LOCK TABLE WRITE" to do update, this is why I got Deadlock. - REMOVE ID
2)  CHANNEL_ID - is not indexed by default - ADD Index:
alter table log_DB.TABLE_NAME add index idx_2 (CHANNEL_ID);
Every time you need to comment out drop index if you do SQL schema changes from PDI otherwise PDI will remove it.
3) If possible decrease number of logged lines(it will also speed up insert).
4) Don't use "Log record timeout(in days)". Solution: do delete from table in separate Job/transformation.
5) It's better to create primary key for table:
alter table log_DB.TABLE_NAME add column id int primary key auto_increment;


To Pentaho team: looks like it's very old problem. I spent 1 hour to find solution that work for me.... Why can't you fix it?

Bug:
https://jira.pentaho.com/browse/PDI-2054

My version is 8.2 0_o

surprise with "Start slave" on MySQL from python

I worked on some tool that checks slave status and starts it in some cases automatically. Here is strange MySQL(Percona in my case) behaviour that I stepped on. 

Topology is: Master->Slave.(Multi-threaded replication).

Important slave configuration: Master_Info_File: mysql.slave_master_info,

Script logic is pretty simple:

1. Connect to DB
2. Get Slave status
3. Check if it's my case
4. Start slave
5. Get Slave status & and return a result.

From first glance it looks correct and I started to test it and got some unexpected results: start slave got locked and script was waiting, at this point of time it was not clear... I started to investigate the issue.

See part of innodb status:

------- TRX HAS BEEN WAITING 20 SEC FOR THIS LOCK TO BE GRANTED:

RECORD

LOCKS space id 5 page no 3 n bits 88 index `PRIMARY` of table

`mysql`.`slave_worker_info` trx id 1687457 lock mode S waiting

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

---TRANSACTION

1687450, ACTIVE 262 sec

4

lock struct(s), heap size 1184, 10 row lock(s)

MySQL

thread id 55, OS thread handle 0x7f4748d43700, query id 1260 XX.XX.XX.XX

[username] Waiting for slave thread to start

text unavailable>

Thread #55 is a connect from my tool. First one is system slave thread. It looking as Deadlock, let me explain my thoughts:

By default at least python(MySQL-python)works with autocommit=OFF(I think most of MySQL libs for various scripting languages works so). When script gets slave status it holds a lock because master_info_repository=TABLE, and if you check engine of the tables(mysql.slave_master_info) they are InnoDB.

Connect #55 was trying to start slave, system tread waited for releasing lock `mysql`.`slave_worker_info` table, that was taken by #55.

Was fixed by enabling autocommit for connection.

#MySQL #Percona #Python

Comparing mydumper vs pure mysqldump

Today I tested mydumper.

It showed very cool results, see below.

Data size + index size is 9054MB. Here is timing of dumping/restoring the same database using mydumper vs mysqldump.

     |  mysqldump/restore dump |mydumper/loader
dump   | real    1m36.642s     |real    0m49.342s
restore| real    32m32.732s     |real    20m32.215s

Also during compilation I faced with issue:

mydumper.c:2814: error: ‘MYSQL_TYPE_JSON’ undeclared (first use in this function)
mydumper.c:2814: error: (Each undeclared identifier is reported only once
mydumper.c:2814: error: for each function it appears in.)
make[2]: *** [CMakeFiles/mydumper/mydumper.c.o] Error 1
make[1]: *** [CMakeFiles/mydumper/all] Error 2
make: *** [all] Error 2

Probably because I am using Percoan 5.6 dev package and JSON data type was introduced only in 5.7. I have commented 2 lines with the 

./mydumper.c: /* if (fields[i].type == MYSQL_TYPE_JSON) g_string_append(statement_row, "CONVERT("); */

./mydumper.c: /* if (fields[i].type == MYSQL_TYPE_JSON) g_string_append(statement_row, " USING UTF8MB4)"); */

I hope it will not affect me unless I am using 5.7+.

Доходчиво про индексы MySQL

Ссылка для прочтения.

Troubleshooting row-based replication issues

Hi,

I would like to describe my problem: one of slave server got a permanent issue with replication delay, there was a setup with following topology:
master--STATEMANET BINLOG-->slave1--ROW format-->slave2-ROW format.

Slave2 had replication delay that was continuously increasing.


One of the slave thread in processlist:

*************************** 3. row ***************************
         User: system user
         Host:
           db: NULL
      Command: Connect
         Time: 8935374
        State: Reading event from the relay log
         Info: NULL
    Rows_sent: 0
Rows_examined: 0

           Id: 5

Part of "show engine innodb status":

---TRANSACTION 4675333, ACTIVE 17629 sec fetching rows
mysql tables in use 1, locked 1
28346 lock struct(s), heap size 2618920, 1921370 row lock(s), undo log entries 3220
MySQL thread id 5, OS thread handle 0x7f8c8060e700, query id 21 Reading event from the relay log

Hm, what is going on? No queries in processlist. Then I checked what was in positions in relay logs form show slave status command:

mysql> show slave status\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: X.X.X.X
                  Master_User: XXXXX
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: db-xxx-bin.001368
          Read_Master_Log_Pos: 9430623
               Relay_Log_File: db-xxx-relay.001192
                Relay_Log_Pos: 409141308        Relay_Master_Log_File: db-xxx-bin.001290
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes

sudo mysqlbinlog -v  --base64-output=DECODE-ROWS --start-position=409141308  db-xxx-relay.001192:

SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=8/*!*/;
SET @@session.time_zone='SYSTEM'/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 409141389
#160618 20:06:24 server id 701020101  end_log_pos 409141521 CRC32 0x04f7b62f    Table_map: `db`.`TABLE` mapped to number 1002
# at 409141685
#160618 20:06:24 server id 701020101  end_log_pos 409149640 CRC32 0xaad0c198    Delete_rows: table id 1002
# at 409149804
#160618 20:06:24 server id 701020101  end_log_pos 409157762 CRC32 0x7f27178b    Delete_rows: table id 1002
# at 409157926
#160618 20:06:24 server id 701020101  end_log_pos 409165890 CRC32 0x118c26ad    Delete_rows: table id 1002
# at 409166054
#160618 20:06:24 server id 701020101  end_log_pos 409173977 CRC32 0x137acdbd    Delete_rows: table id 1002
# at 409174141

.....

So here we can see that  table "TABLE" is being cleaned up by some clause. I would like to add that this table contains a lot of records, let's find out SQL code(we use -v  --base64-output=DECODE-ROWS options):

...

#160618 20:06:24 server id 701020101  end_log_pos 928334665 CRC32 0x790815e0    Delete_ro
ws: table id 1002 flags: STMT_END_F
### DELETE FROM `db`.`TABLE`
### WHERE
###   @1='data1'
###   @2='data2'
###   @3='data3'
###   @4=86561281
###   @5='data3'
###   @6=2016-09-13 14:00:00
###   @7=1111
###   @8='Friday'
###   @9='14:30'
###   @10='14:00'
###   @11=14
###   @12='May'
###   @13='14:10'
###   @14='14:13:57'
###   @15=NULL
###   @16=2016-06-13 14:43:57
###   @17=2016
..... 

So  there is DELETE statement for each row with clause that includes every column. I mentioned that the table is pretty big, that is why we got replication delay. I checked table TABLE definition and found that it had been created without primary key definition. And "DELETE from TABLE where column <> 'data1'"(as example) created a lot of events in binary log of slave1. Slave2 have to perform full scan for each record. I'll try to fix it by creating appropriate primary key on master server.

Understand right file_per_table=ON

Let's imagine situation:

You have 100 DBs on your MySQL server and in some point of time you realised that your InnoDB space had been consumed on 80% and you chosen to migrate to file_per_table, luckily it is a dynamic parameter. Well, it's a good idea if you have enough disk space on the host. It easer than adding additional InnoDB file right? You ACKed the alert in your monitoring system and forgot this problem.

This is wrong approach, I will explain why:
It will use separate tablespace only for newly created tables, and if you have some growing tables in system tablespace, it will keep on consuming system INNODB. Don't forget to move tables to separate file by altering table.

How to find tables in SYSTEM InnoDB space:
Select NAME from information_schema.INNODB_SYS_TABLES where SPACE =0 and name not like "SYS_%";

According to MySQL docs SPACE =0 means that it is using SYSTEM InnoDB space.

mysql pam_auth problem on MacOs

I tried to use pam auth using mysql client on MacBook. I got the error below using percona/orcale mysql binaries:

mysql -hxxx.yyy.com -p -uUSER
Enter password:
ERROR 2059 (HY000): Authentication plugin 'dialog' cannot be loaded: dlopen(/opt/local/lib/percona/plugin/dialog.so, 2): image not found


How to fix:
You can install mariadb bins from ports collections and use mariadb's mysql bin. But I just copied "mariadb/plugin/dialog.so" lib to my percona's plugin directory. It works fine.

Extracting DB dump from archive with multiple DBs

Hello.

Today I'm going to explain how to extract mysql DB dump from a file with multiple DBs. Some time ago I used sed command to perform such tasks, but this method has some problems:

Let me show how to do this with sed:

cat/bzcat /path/to/file | sed -n '/^USE `DB_TO_RESTORE`/,/^USE /p'

to resotore TABLE_TO_RESTORE  table:
cat/bzcat /path/to/file | sed -n '/^DROP TABLE IF EXISTS `TABLE_TO_RESTORE`/,/^DROP TABLE IF EXISTS /p'

Or combine the commands above: =)

to restore DB_TO_RESTORE.TABLE_TO_RESTORE table:
cat/bzcat /path/to/file | sed -n '/^USE `DB_TO_RESTORE`/,/^USE /p' | | sed -n '/^DROP TABLE IF EXISTS `TABLE_TO_RESTORE`/,/^DROP TABLE IF EXISTS /p'

Problem with this method:
What about multiple mysql tables to restore with sed? Probably it is possible, but I'm not a sed hacker =)
What if /path/to/file is pretty big, sed will work until whole the file is processed, even if all needed data already restored...

To avoid this I created perl script that restores needed data and stops to process incoming data. Here you go: extractor.pl.

mysqldump commands will be printed to STDOUT, all information will be printed to STDERR.

Example:
cat dump.sql | extractor.pl DB table1 table2 > result.sql
db= DB, tables: table1 table2
DB # <- current="" db.="" nbsp="" p="">    table: XXX # <- current="" p="" table="">    table: XXXY
    table: ZZZZ
    table: DDD
    table: table1
    table: table2

Script stops working once it processed "DB" database.


Enjoy!