MySQL 8 VS MariaDB 10.2 / 3천만 대량 Row Restore 작업후기

* 대상

뉴스 제목, 언론사 명 및 관리용 컬럼으로 구성된 테이블

약 3천만 Row

SQL 파일 약 30GB

* 환경 - 2012 년경 구입한 데스크탑

CPU AMD-A8 / 4 core / 2.9GHz

16gb ram

win 7

MariaDB 10.2

* 사건 개요

고물 컴퓨터 / Windows 7 / MySQL 5.5 환경에서 뉴스 수집과 정리를 하고 있었음.

돌아가는데는 큰 지장이 없었지만 더 나은 버전으로 마이그레이션 하기로 함.

인덱스가 워낙 많고, Full text Index 도 있는 상태.

MySQL 과 MariaDB 고민 끝에 MariaDB 10.2 로 결정

MySQL 5.5 에서 MariaDB 10.2 로는 옮겨갈 수 없기에 SQL 로 덤프해서 옮기기로 함.

SQL 은 진행 상황 확인, 중단시 재개 고려하여 1000개 Row 씩 잘라서 만듦.

MariaDB 10.2 로 Import 시작했으나 27시간 쯤에 종료 1/3 인 천만개 정도 데이터가 들어가 있음. MySQL 서비스는 종료되어 있음.

재시작, 중단된 부분부터 Import 재개 

그러나 이렇게 중간에 끊어지는 현상이 반복됨. 

반복되는 내용은 다음과 같음

1. Import 중단, MySQL 서비스 중단

2. net start MySQL 실행하면 바로 시작되는게 아니라 RollBack 작업이라며 무언가 한참 걸림. - 콘솔에서 확인되는건 아니고 로그 확인해야 함.

(아래의 로그 확인)

3. Import 재개하면 시작되었다가 동일 과정 반복됨.

그러다 2천만 개 도달했을때는 남은 1천만개 임포트 불가능 할 정도로 느려짐

(종료 시간 추정 계산해보니 20일 정도...)

- 다른 컴퓨터로도 해봤는데 결국 동일하게 안되더라.

- 근데 MySQL 8 깔아서 다시 해보니 잘 됨..

* 결론

물론 환경이 나쁘다든지, 내가 뭘 잘 못 했다든지 하겠지만.. 

개인적으론 MariaDB 는 다시 쓰고 싶지 않음..

* net start MySQL(마리아 DB 서비스 시작) 했을 때의 MariaDB 에러 로그파일 확인 

- 다음과 같은 로그가 주기적으로 몇분에 한번씩 Restore 진행 중에 계속 생성됨

- 큰 문제가 있는 부분은 아닌 듯... 

... 전략 ...

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

END OF INNODB MONITOR OUTPUT

============================

InnoDB: ###### Diagnostic info printed to the standard error stream

2018-04-25 20:37:40 1176 [Warning] InnoDB: A long semaphore wait:

--Thread 2188 has waited at fts0fts.cc line 3623 for 924.00 seconds the semaphore:

X-lock on RW-latch at 0000000070A9FB40 created in file fts0fts.cc line 636

a writer (thread id 4032) has reserved it in mode  exclusive

number of readers 0, waiters flag 1, lock_word: 0

Last time read locked in file not yet reserved line 0

Last time write locked in file fts0fts.cc line 4113

2018-04-25 20:37:40 1176 [Note] InnoDB: A semaphore wait:

--Thread 4032 has waited at buf0buf.cc line 3589 for 0.00 seconds the semaphore:

Mutex at 0000000001CB61B0, Mutex BUF_POOL created buf0buf.cc:1757, lock var 0

2018-04-25 20:37:40 1176 [Note] InnoDB: A semaphore wait:

--Thread 2188 has waited at fts0fts.cc line 3623 for 924.00 seconds the semaphore:

X-lock on RW-latch at 0000000070A9FB40 created in file fts0fts.cc line 636

a writer (thread id 4032) has reserved it in mode  exclusive

number of readers 0, waiters flag 1, lock_word: 0

Last time read locked in file not yet reserved line 0

Last time write locked in file fts0fts.cc line 4113

InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:

InnoDB: Pending reads 1, writes 0

=====================================

2018-04-25 20:37:56 0x230 INNODB MONITOR OUTPUT

=====================================

Per second averages calculated from the last 20 seconds

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

BACKGROUND THREAD

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

srv_master_thread loops: 27214 srv_active, 0 srv_shutdown, 11296 srv_idle

srv_master_thread log flush and writes: 38510

----------

SEMAPHORES

----------

OS WAIT ARRAY INFO: reservation count 722506

--Thread 4032 has waited at buf0buf.cc line 3589 for 0.00 seconds the semaphore:

Mutex at 0000000001CB61B0, Mutex BUF_POOL created buf0buf.cc:1757, lock var 2

--Thread 2188 has waited at fts0fts.cc line 3623 for 940.00 seconds the semaphore:

X-lock on RW-latch at 0000000070A9FB40 created in file fts0fts.cc line 636

a writer (thread id 4032) has reserved it in mode  exclusive

number of readers 0, waiters flag 1, lock_word: 0

Last time read locked in file not yet reserved line 0

Last time write locked in file fts0fts.cc line 4113

OS WAIT ARRAY INFO: signal count 567285

RW-shared spins 0, rounds 340984, OS waits 169079

RW-excl spins 0, rounds 9182386, OS waits 173518

RW-sx spins 35200, rounds 236029, OS waits 3648

Spin rounds per wait: 340984.00 RW-shared, 9182386.00 RW-excl, 6.71 RW-sx

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

TRANSACTIONS

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

Trx id counter 76167

Purge done for trx's n:o < 75693 undo n:o < 0 state: running but idle

History list length 0

LIST OF TRANSACTIONS FOR EACH SESSION:

---TRANSACTION 281475142715792, not started

0 lock struct(s), heap size 1136, 0 row lock(s)

---TRANSACTION 281475142714208, not started

0 lock struct(s), heap size 1136, 0 row lock(s)

---TRANSACTION 76166, ACTIVE 940 sec

0 lock struct(s), heap size 1136, 0 row lock(s)

---TRANSACTION 76165, ACTIVE 941 sec committing

mysql tables in use 3, locked 3

1 lock struct(s), heap size 1136, 0 row lock(s), undo log entries 1000

MySQL thread id 14770, OS thread handle 2188, query id 414530 localhost ::1 root query end

INSERT INTO `concrete_info_overview` VALUES (23247001,NULL,NULL,35,NULL,NULL,NULL,NULL,'http://news.naver.com/main/read.nhn?mode=LPOD&mid=sec&oid=119&aid=0002070916','2015-04-02 14:11:00','Task_CollectCioByCip','news.naver.com','161224_1','\0',NULL,'\0','\0','\0','\0','\0',NULL,NULL,NULL,'데일리안',NULL,'2017-09-20 09:13:48',NULL,NULL,NULL,'아우디코리아, 뉴 A6·S6·A7·S7 등 8종 국내 최초 공개','데일리안',NULL,'\0',NULL,NULL,'\0',NULL,NULL,NULL,NULL,NULL,0,NULL,0),(23247002,NULL,NULL,34,NULL,NULL,NULL,NULL,'http://news.naver.com/main/read.nhn?mode=LPOD&mid=sec&oid=079&ai

---TRANSACTION 75698, ACTIVE 1505 sec doing SYNC index

6 lock struct(s), heap size 1136, 0 row lock(s), undo log entries 140126

--------

FILE I/O

--------

I/O thread 0 state: native aio handle (insert buffer thread)

I/O thread 1 state: native aio handle (log thread)

I/O thread 2 state: native aio handle (read thread)

I/O thread 3 state: native aio handle (read thread)

I/O thread 4 state: native aio handle (read thread)

I/O thread 5 state: native aio handle (read thread)

I/O thread 6 state: native aio handle (write thread)

I/O thread 7 state: complete io for buf page (write thread)

I/O thread 8 state: native aio handle (write thread)

I/O thread 9 state: native aio handle (write thread)

Pending normal aio reads: [0, 0, 0, 0] , aio writes: [0, 0, 0, 0] ,

 ibuf aio reads:, log i/o's:, sync i/o's:

Pending flushes (fsync) log: 0; buffer pool: 1

636179 OS file reads, 9442202 OS file writes, 657965 OS fsyncs

24.80 reads/s, 16384 avg bytes/read, 104.49 writes/s, 9.75 fsyncs/s

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

INSERT BUFFER AND ADAPTIVE HASH INDEX

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

Ibuf: size 1, free list len 2075, seg size 2077, 232014 merges

merged operations:

 insert 3354702, delete mark 0, delete 0

discarded operations:

 insert 0, delete mark 0, delete 0

Hash table size 553253, node heap has 6 buffer(s)

Hash table size 553253, node heap has 1 buffer(s)

Hash table size 553253, node heap has 12 buffer(s)

Hash table size 553253, node heap has 1 buffer(s)

Hash table size 553253, node heap has 233 buffer(s)

Hash table size 553253, node heap has 1 buffer(s)

Hash table size 553253, node heap has 267 buffer(s)

Hash table size 553253, node heap has 17 buffer(s)

0.00 hash searches/s, 100.04 non-hash searches/s

---

LOG

---

Log sequence number 18410763507

Log flushed up to   18410751208

Pages flushed up to 18404863834

Last checkpoint at  18404763634

0 pending log flushes, 0 pending chkp writes

107898 log i/o's done, 1.75 log i/o's/second

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

BUFFER POOL AND MEMORY

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

Total large memory allocated 2199912448

Dictionary memory allocated 358821

Buffer pool size   131072

Free buffers       2

Database pages     130532

Old database pages 48079

Modified db pages  15681

Percent of dirty pages(LRU & free pages): 12.013

Max dirty pages percent: 75.000

Pending reads 0

Pending writes: LRU 0, flush list 2, single page 0

Pages made young 1634889, not young 2363101

0.00 youngs/s, 38.70 non-youngs/s

Pages read 636164, created 986951, written 9101679

24.75 reads/s, 0.90 creates/s, 98.80 writes/s

Buffer pool hit rate 942 / 1000, young-making rate 0 / 1000 not 89 / 1000

Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s

LRU len: 130532, unzip_LRU len: 0

I/O sum[625792]:cur[15944], unzip sum[0]:cur[0]

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

INDIVIDUAL BUFFER POOL INFO

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

---BUFFER POOL 0

Buffer pool size   16384

Free buffers       0

Database pages     16309

Old database pages 6002

Modified db pages  1765

Percent of dirty pages(LRU & free pages): 10.822

Max dirty pages percent: 75.000

Pending reads 0

Pending writes: LRU 0, flush list 0, single page 0

Pages made young 203650, not young 262441

0.00 youngs/s, 4.50 non-youngs/s

Pages read 75109, created 122718, written 1139199

2.95 reads/s, 0.00 creates/s, 12.55 writes/s

Buffer pool hit rate 754 / 1000, young-making rate 0 / 1000 not 375 / 1000

Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s

LRU len: 16309, unzip_LRU len: 0

I/O sum[78224]:cur[1993], unzip sum[0]:cur[0]

---BUFFER POOL 1

Buffer pool size   16384

Free buffers       0

Database pages     16319

Old database pages 6004

Modified db pages  2377

Percent of dirty pages(LRU & free pages): 14.565

Max dirty pages percent: 75.000

Pending reads 0

Pending writes: LRU 0, flush list 0, single page 0

Pages made young 211675, not young 350075

0.00 youngs/s, 3.60 non-youngs/s

Pages read 80945, created 121445, written 1154389

2.35 reads/s, 0.85 creates/s, 12.50 writes/s

Buffer pool hit rate 980 / 1000, young-making rate 0 / 1000 not 29 / 1000

Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s

LRU len: 16319, unzip_LRU len: 0

I/O sum[78224]:cur[1993], unzip sum[0]:cur[0]

---BUFFER POOL 2

Buffer pool size   16384

Free buffers       0

Database pages     16320

Old database pages 6024

Modified db pages  1914

Percent of dirty pages(LRU & free pages): 11.727

Max dirty pages percent: 75.000

Pending reads 0

Pending writes: LRU 0, flush list 0, single page 0

Pages made young 209061, not young 319025

0.00 youngs/s, 5.65 non-youngs/s

Pages read 81522, created 124076, written 1149286

3.75 reads/s, 0.00 creates/s, 12.50 writes/s

Buffer pool hit rate 840 / 1000, young-making rate 0 / 1000 not 240 / 1000

Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s

LRU len: 16320, unzip_LRU len: 0

I/O sum[78224]:cur[1993], unzip sum[0]:cur[0]

---BUFFER POOL 3

Buffer pool size   16384

Free buffers       1

Database pages     16313

Old database pages 6012

Modified db pages  2408

Percent of dirty pages(LRU & free pages): 14.759

Max dirty pages percent: 75.000

Pending reads 0

Pending writes: LRU 0, flush list 0, single page 0

Pages made young 214093, not young 286751

0.00 youngs/s, 4.85 non-youngs/s

Pages read 83509, created 123698, written 1153308

3.35 reads/s, 0.00 creates/s, 12.50 writes/s

Buffer pool hit rate 874 / 1000, young-making rate 0 / 1000 not 181 / 1000

Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s

LRU len: 16313, unzip_LRU len: 0

I/O sum[78224]:cur[1993], unzip sum[0]:cur[0]

---BUFFER POOL 4

Buffer pool size   16384

Free buffers       0

Database pages     16317

Old database pages 6011

Modified db pages  1816

Percent of dirty pages(LRU & free pages): 11.129

Max dirty pages percent: 75.000

Pending reads 0

Pending writes: LRU 0, flush list 0, single page 0

Pages made young 198779, not young 283916

0.00 youngs/s, 5.15 non-youngs/s

Pages read 76714, created 123797, written 1128895

3.05 reads/s, 0.00 creates/s, 12.50 writes/s

Buffer pool hit rate 980 / 1000, young-making rate 0 / 1000 not 32 / 1000

Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s

LRU len: 16317, unzip_LRU len: 0

I/O sum[78224]:cur[1993], unzip sum[0]:cur[0]

---BUFFER POOL 5

Buffer pool size   16384

Free buffers       0

Database pages     16318

Old database pages 6010

Modified db pages  1418

Percent of dirty pages(LRU & free pages): 8.689

Max dirty pages percent: 75.000

Pending reads 0

Pending writes: LRU 0, flush list 2, single page 0

Pages made young 193532, not young 263159

0.00 youngs/s, 5.45 non-youngs/s

Pages read 75070, created 124064, written 1109162

3.60 reads/s, 0.00 creates/s, 11.25 writes/s

Buffer pool hit rate 728 / 1000, young-making rate 0 / 1000 not 411 / 1000

Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s

LRU len: 16318, unzip_LRU len: 0

I/O sum[78224]:cur[1993], unzip sum[0]:cur[0]

---BUFFER POOL 6

Buffer pool size   16384

Free buffers       0

Database pages     16316

Old database pages 6006

Modified db pages  1832

Percent of dirty pages(LRU & free pages): 11.228

Max dirty pages percent: 75.000

Pending reads 0

Pending writes: LRU 0, flush list 0, single page 0

Pages made young 200801, not young 295363

0.00 youngs/s, 4.50 non-youngs/s

Pages read 81484, created 123287, written 1131392

2.70 reads/s, 0.00 creates/s, 12.50 writes/s

Buffer pool hit rate 955 / 1000, young-making rate 0 / 1000 not 73 / 1000

Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s

LRU len: 16316, unzip_LRU len: 0

I/O sum[78224]:cur[1993], unzip sum[0]:cur[0]

---BUFFER POOL 7

Buffer pool size   16384

Free buffers       1

Database pages     16320

Old database pages 6010

Modified db pages  2151

Percent of dirty pages(LRU & free pages): 13.179

Max dirty pages percent: 75.000

Pending reads 0

Pending writes: LRU 0, flush list 0, single page 0

Pages made young 203298, not young 302371

0.00 youngs/s, 5.00 non-youngs/s

Pages read 81811, created 123866, written 1136048

3.00 reads/s, 0.05 creates/s, 12.50 writes/s

Buffer pool hit rate 792 / 1000, young-making rate 0 / 1000 not 346 / 1000

Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s

LRU len: 16320, unzip_LRU len: 0

I/O sum[78224]:cur[1993], unzip sum[0]:cur[0]

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

ROW OPERATIONS

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

0 queries inside InnoDB, 0 queries in queue

0 read views open inside InnoDB

Process ID=3236, Main thread ID=1724, state: sleeping

Number of rows inserted 30749853, updated 0, deleted 0, read 328000

0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s

Number of system rows inserted 0, updated 0, deleted 0, read 0

0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s

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

END OF INNODB MONITOR OUTPUT

============================

- 실제 오류 발생 부분

작업 시작한지 약 14시간 (종료는 27시간) 즈음에 오류가 있었음.

InnoDB: ###### Diagnostic info printed to the standard error stream

2018-04-25 20:38:10 1176 [ERROR] [FATAL] InnoDB: Semaphore wait has lasted > 600 seconds. We intentionally crash the server because it appears to be hung.

180425 20:38:10 [ERROR] mysqld got exception 0x80000003 ;

This could be because you hit a bug. It is also possible that this binary

or one of the libraries it was linked against is corrupt, improperly built,

or misconfigured. This error can also be caused by malfunctioning hardware.

To report this bug, see https://mariadb.com/kb/en/reporting-bugs

We will try our best to scrape up some info that will hopefully help

diagnose the problem, but since we have already crashed, 

something is definitely wrong and this may fail.

Server version: 10.2.14-MariaDB

key_buffer_size=134217728

read_buffer_size=131072

max_used_connections=3

max_threads=65537

thread_count=8

It is possible that mysqld could use up to 

key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 136058 K  bytes of memory

Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0

Attempting backtrace. You can use the following information to find out

where mysqld died. If you see no messages after this, something went

terribly wrong...

mysqld.exe!my_parameter_handler()[my_init.c:256]

mysqld.exe!raise()[signal.cpp:516]

mysqld.exe!abort()[abort.cpp:71]

mysqld.exe!ib::fatal::~fatal()[ut0ut.cc:792]

mysqld.exe!srv_error_monitor_thread()[srv0srv.cc:1903]

kernel32.dll!BaseThreadInitThunk()

ntdll.dll!RtlUserThreadStart()

The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains

information that should help you find out what is causing the crash.

* 서비스가 중단되어 있길래 재기동 시키자 자체 자체 작업을 수행함.

- 서비스 중단은 오류 발생 시점이 아니고, 모든 Insert 작업 끝난 이후로 추정

- 다만 오류 발생 후 실행된 Insert 는 Commit 이 되지 않았거나 오류가 있어서 작업을 완료하지 못한듯함.

- 오류 원인이나, 그에 대한 해결책은 몰라.

2018-04-26 12:04:12 5864 [Note] InnoDB: Mutexes and rw_locks use Windows interlocked functions

2018-04-26 12:04:12 5864 [Note] InnoDB: Uses event mutexes

2018-04-26 12:04:12 5864 [Note] InnoDB: Compressed tables use zlib 1.2.3

2018-04-26 12:04:12 5864 [Note] InnoDB: Number of pools: 1

2018-04-26 12:04:12 5864 [Note] InnoDB: Using generic crc32 instructions

2018-04-26 12:04:12 5864 [Note] InnoDB: Initializing buffer pool, total size = 2G, instances = 8, chunk size = 128M

2018-04-26 12:04:12 5864 [Note] InnoDB: Completed initialization of buffer pool

2018-04-26 12:04:12 5864 [Note] InnoDB: Highest supported file format is Barracuda.

2018-04-26 12:04:12 5864 [Note] InnoDB: Starting crash recovery from checkpoint LSN=18560749193

2018-04-26 12:04:15 5864 [Note] InnoDB: 2 transaction(s) which must be rolled back or cleaned up in total 95475 row operations to undo

2018-04-26 12:04:15 5864 [Note] InnoDB: Trx id counter is 76800

2018-04-26 12:04:15 5864 [Note] InnoDB: Starting final batch to recover 47790 pages from redo log.

2018-04-26 12:04:27 5904 [Note] InnoDB: To recover: 39143 pages from log

2018-04-26 12:04:42 5904 [Note] InnoDB: To recover: 25085 pages from log

2018-04-26 12:04:57 5904 [Note] InnoDB: To recover: 12183 pages from log

2018-04-26 12:05:12 5904 [Note] InnoDB: To recover: 23 pages from log

2018-04-26 12:05:12 5864 [Note] InnoDB: 128 out of 128 rollback segments are active.

2018-04-26 12:05:12 6136 [Note] InnoDB: Starting in background the rollback of recovered transactions

2018-04-26 12:05:12 5864 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"

2018-04-26 12:05:12 5864 [Note] InnoDB: Creating shared tablespace for temporary tables

2018-04-26 12:05:12 5864 [Note] InnoDB: Setting file '.\ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...

2018-04-26 12:05:12 5864 [Note] InnoDB: File '.\ibtmp1' size is now 12 MB.

2018-04-26 12:05:12 5864 [Note] InnoDB: 5.7.21 started; log sequence number 18560749693

2018-04-26 12:05:12 6044 [Note] InnoDB: Loading buffer pool(s) from C:\Program Files\MariaDB 10.2\data\ib_buffer_pool

2018-04-26 12:05:12 5864 [Note] Plugin 'FEEDBACK' is disabled.

2018-04-26 12:05:12 5864 [Note] Server socket created on IP: '::'.

2018-04-26 12:05:13 5864 [Note] Reading of all Master_info entries succeded

2018-04-26 12:05:13 5864 [Note] Added new Master_info '' to hash table

2018-04-26 12:05:13 5864 [Note] C:\Program Files\MariaDB 10.2\bin\mysqld.exe: ready for connections.

Version: '10.2.14-MariaDB'  socket: ''  port: 3306  mariadb.org binary distribution

2018-04-26 12:05:13 6044 [Note] InnoDB: Buffer pool(s) load completed at 180426 12:05:13

2018-04-26 12:05:19 6136 [Note] InnoDB: Rolled back recovered transaction 76521

2018-04-26 12:05:27 6136 [Note] InnoDB: To roll back: 1 transactions, 93555 rows

2018-04-26 12:05:42 6136 [Note] InnoDB: To roll back: 1 transactions, 92265 rows

2018-04-26 12:05:57 6136 [Note] InnoDB: To roll back: 1 transactions, 91099 rows

2018-04-26 12:06:12 6136 [Note] InnoDB: To roll back: 1 transactions, 89531 rows

2018-04-26 12:06:27 6136 [Note] InnoDB: To roll back: 1 transactions, 87960 rows

2018-04-26 12:06:42 6136 [Note] InnoDB: To roll back: 1 transactions, 86607 rows

2018-04-26 12:06:57 6136 [Note] InnoDB: To roll back: 1 transactions, 84986 rows

2018-04-26 12:07:12 6136 [Note] InnoDB: To roll back: 1 transactions, 83845 rows

2018-04-26 12:07:27 6136 [Note] InnoDB: To roll back: 1 transactions, 82451 rows

2018-04-26 12:07:42 6136 [Note] InnoDB: To roll back: 1 transactions, 81189 rows

2018-04-26 12:07:57 6136 [Note] InnoDB: To roll back: 1 transactions, 79726 rows

... 후략 ...

다행히 40분쯤 후에 롤백 작업은 종료되었음.

해당 테이블에는 1/3 인 1000만 Row 정도 Insert 되어 있는 상태