รบกวนช่วยแนะนำแนวทางแก้ปัญหา error mysql ทีนะคร้าบ

Technical topics
#1

ขออนุญาติรบกวนพี่ๆ นิดนึงนะครับ พอดีช่วงนี้ Server ตัวนึงมีปัญหาครับ แต่ไม่ทราบว่าเกิดจากอะไรครับ
เลยอยากจะขอความกรุณาพี่ๆ ช่วยแนะนำแนวทางแก้ไขให้หน่อยครับ ขอเขียนยาวหน่อยนะครับ จะได้อธิบายละเอียดๆ ครับ

ปัญหาที่เกิดขึ้นคือ Server จะมี Load Average ขึ้น เป็นประจำครับ เกือบทุกวัน ทำให้เว็บในเครื่องที่ใช้งานในช่วงเวลานั้นเข้าถึงได้ช้ากว่าปกติ
ช่วงเวลาที่พบปัญหาจะแตกต่างกันออกไป บางวันเป็นบางวันไม่เป็นครับ
ถ้าวันไหนเป็นส่วนใหญ่จะเกิดเวลากลางวันครับ 9 โมงเช้าบ้าง 11 โมงเช้าบ้าง บ่ายโมงบ้าง บ่ายสามบ้าง สี่โมงเย็นบ้าง

ซึ่งไม่ใช่ช่วงเวลาที่มี การเข้าใช้งานสูงมากนัก ตรวจสอบจาก กราฟ MRTG
และไม่ใช่ช่วงเวลาที่ Server ทำ Backup ครับ

รายละเอียด TOP ช่วงเวลาที่พบปัญหา
@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-
This is an automated message notifying you that the 5 minute load average on your system is 15.2.
This has exceeded the 10 threshold.

One Minute- 34.39
Five Minutes - 15.2
Fifteen Minutes - 7.51

top - 11:21:02 up 150 days, 13:54,0 users,load average: 34.39, 15.20, 7.51
Tasks: 764 total,3 running, 760 sleeping,0 stopped,1 zombie
Cpu(s): 11.4%us,6.4%sy,0.6%ni, 80.5%id,0.9%wa,0.0%hi,0.2%si,0.0%st
Mem:32881704k total, 30881944k used,1999760k free,480748k buffers
Swap: 16779884k total,228k used, 16779656k free, 21255072k cached

PID USERPRNIVIRTRESSHR S %CPU %MEM TIME+COMMAND
30720 mysql150752m 254m 5896 S 144.10.891924:16 /usr/sbin/mysqld --basedir=/ --datadir=/var/lib/mysql --user=mysql --log-error=/var/lib/mysql/sv1.hostname.com.err --pid-file=/var/lib/mysql/sv1.hostname.com.pid
4095 apache 160176m65m 5064 R 82.40.20:05.27 /usr/sbin/httpd -k start -DSSL
5114 apache 160178m68m 4232 S 69.30.20:01.74 /usr/sbin/httpd -k start -DSSL
5738 apache 160169m60m 4324 S 59.90.20:01.25 /usr/sbin/httpd -k start -DSSL
5701 apache 160196m33m 4248 S 48.70.10:00.38 /usr/sbin/httpd -k start -DSSL
5078 apache 160161m52m 4292 R 29.90.20:02.39 /usr/sbin/httpd -k start -DSSL
6132 root160 13280 1540744 R5.60.00:00.04 /usr/bin/top -c -b -n 1
8 rootRT-50 0 0 S1.90.03:10.22 [migration/2]
2193 apache 150227m64m 6136 S1.90.20:12.07 /usr/sbin/httpd -k start -DSSL
2911 apache 150224m61m 5724 S1.90.20:08.14 /usr/sbin/httpd -k start -DSSL
4119 apache 150217m53m 5540 S1.90.20:05.78 /usr/sbin/httpd -k start -DSSL
5102 apache 150171m61m 4588 S1.90.20:01.24 /usr/sbin/httpd -k start -DSSL
1 root150 10364696584 S0.00.02:26.84 init [3]
2 rootRT-50 0 0 S0.00.00:01.75 [migration/0]
3 root34190 0 0 S0.00.00:10.42 [ksoftirqd/0]
4 rootRT-50 0 0 S0.00.00:00.00 [watchdog/0]
5 rootRT-50 0 0 S0.00.04:18.34 [migration/1]
6 root34190 0 0 S0.00.02:09.79 [ksoftirqd/1]
7 rootRT-50 0 0 S0.00.00:00.00 [watchdog/1]
9 root34190 0 0 S0.00.01:37.46 [ksoftirqd/2]
10 rootRT-50 0 0 S0.00.00:00.00 [watchdog/2]
11 rootRT-50 0 0 S0.00.04:22.12 [migration/3]
12 root34190 0 0 S0.00.01:32.03 [ksoftirqd/3]
@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-

จากการสังเกตุผมว่าปัญหาต้องเกิดจาก
30720 mysql150752m 254m 5896 S 144.10.891924:16 /usr/sbin/mysqld --basedir=/ --datadir=/var/lib/mysql --user=mysql --log-error=/var/lib/mysql/sv1.hostname.com.err --pid-file=/var/lib/mysql/sv1.hostname.com.pid

เจ้านี้แน่ๆ เลย เพราะTOP ช่วงเวลาที่พบปัญหาจะมีตลอด และเป็นตัวที่อยู่บนสุดเสมอครับปกติ ถ้าเวลาไม่พบปัญหา
จะเป็น Service mysqld ที่อยู่บนสุดครับลักษณะนี้
30720 mysql 15 0 788m 290m 5896 S 27.5 0.9 92323:34 mysqld

ผมเลยเข้าไปดู File /var/lib/mysql/sv1.hostname.com.err ตาม log error ที่แจ้งไว้และพบข้อความดังนี้ครับ
@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-
120812 5:07:17 [ERROR] /usr/sbin/mysqld: Can’t open file: ‘./apple_intrend/mxaf0_finder_links_terms9.frm’ (errno: 24)
120812 5:07:17 [ERROR] /usr/sbin/mysqld: Can’t open file: ‘./movieox_forum/pre_common_word_type.frm’ (errno: 24)
120813 5:25:51 [ERROR] /usr/sbin/mysqld: Can’t open file: ‘./dekmap_mybb/demo1_awaitingactivation.frm’ (errno: 24)
120813 5:25:51 [ERROR] /usr/sbin/mysqld: Can’t open file: ‘./pitak_lotded/smf_sessions.frm’ (errno: 24)
120813 5:25:51 [ERROR] /usr/sbin/mysqld: Can’t open file: ‘./pitak_lotded/smf_log_errors.frm’ (errno: 24)
120814 5:23:18 [ERROR] /usr/sbin/mysqld: Can’t open file: ‘./dekmap_mybb/demo1_banned.frm’ (errno: 24)
120815 5:24:58 [ERROR] /usr/sbin/mysqld: Can’t open file: ‘./dekmap_mybb/demo1_adminsessions.frm’ (errno: 24)
120816 5:23:06 [ERROR] /usr/sbin/mysqld: Can’t open file: ‘./dekmap_mybb/demo1_badwords.frm’ (errno: 24)
120817 5:27:26 [ERROR] /usr/sbin/mysqld: Can’t open file: ‘./dekmap_mybb/demo1_announcements.frm’ (errno: 24)
120818 5:22:58 [ERROR] /usr/sbin/mysqld: Can’t open file: ‘./dekmap_mybb/demo1_awaitingactivation.frm’ (errno: 24)
120819 5:06:14 [ERROR] /usr/sbin/mysqld: Can’t open file: ‘./dekmap_mybb/demo1_adminoptions.frm’ (errno: 24)
120819 5:26:29 [ERROR] /usr/sbin/mysqld: Can’t open file: ‘./dekmap_mybb/demo1_announcements.frm’ (errno: 24)
120820 5:23:03 [ERROR] /usr/sbin/mysqld: Can’t open file: ‘./dekmap_mybb/demo1_attachtypes.frm’ (errno: 24)
120821 5:23:55 [ERROR] /usr/sbin/mysqld: Can’t open file: ‘./dekmap_mybb/demo1_calendars.frm’ (errno: 24)
120822 0:19:27 [Note] /usr/sbin/mysqld: Normal shutdown
120822 0:19:27 [Note] Event Scheduler: Purging the queue. 0 events
120822 0:19:29 InnoDB: Starting shutdown…
120822 0:19:34 InnoDB: Shutdown completed; log sequence number 1 3389245333
120822 0:19:34 [Note] /usr/sbin/mysqld: Shutdown complete
120822 00:19:34 mysqld_safe mysqld from pid file /var/lib/mysql/sv1.hostname.com.pid ended
120822 00:19:35 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
120822 0:19:35 [Note] Plugin ‘FEDERATED’ is disabled.
120822 0:19:35 InnoDB: Initializing buffer pool, size = 8.0M
120822 0:19:35 InnoDB: Completed initialization of buffer pool
120822 0:19:35 InnoDB: Started; log sequence number 1 3389245333
120822 0:19:35 [Note] Event Scheduler: Loaded 0 events
120822 0:19:35 [Note] /usr/sbin/mysqld: ready for connections.
Version: ‘5.1.62’ socket: ‘/var/lib/mysql/mysql.sock’ port: 3306 MySQL Community Server (GPL)
@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-

เท่าที่สังเกตุจาก error log พบว่าวันที่ของ error ใน log นั้นล่าสุดเป็นวันที่ 22 เดือน 8 ปี 2012
แต่ปัญหาล่าสุดที่เกิดขึ้นนั้น เพิ่งเกิดเมื่อวันนี้เองครับ (28/10/2012) และเป็นมาแล้วหลายวันติดต่อกัน ในเดือน 10 นี้
แต่ไม่พบ Error log เขียนไว้เลยครับ เลยเกิดสงสัยว่า var เต็มหรือไม่ แต่เข้าไปดูก็ไม่พบว่าเต็มครับ
@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-
Filesystem Size Used Avail Use% Mounted on
/dev/sda5 7.8G 651M 6.8G 9% /
/dev/sda6 872G 22G 806G 3% /var
/dev/sdb1 903G 172G 685G 21% /home
/dev/sdc1 903G 186G 671G 22% /backup
/dev/sda3 7.8G 2.5G 5.0G 33% /usr
/dev/sda1 99M 18M 76M 20% /boot
tmpfs 16G 0 16G 0% /dev/shm
/var/tempFS 7.6G 159M 7.1G 3% /tmp
@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-@-

จึงไม่ทราบจริงๆ ครับว่าปัญหานี้เกิดจากอะไร รบกวนช่วยแนะนำทีนะครับ

ขอบคุณล่วงหน้าครับ

:875328cc:

#2

ดู connect หรือยัง

#3

mysql150752m 254m 5896 S 144.10.891924:16 /usr/sbin/mysqld --basedir=/ --datadir=/var/lib/mysql --user=mysql --log-error=/var/lib/mysql/sv1.hostname.com.err --pid-file=/var/lib/mysql/sv1.hostname.com.pid

ไม่เกี่ยวตรงนี้ไม่ใช่ปัญหา เคสนี้ผมเพิ่งเจอกับตัวเอง และได้แก้ไขไปเรียบร้อยหมดแล้ว. จุดสำคัญอยู่ที่

120817 5:27:26 [ERROR] /usr/sbin/mysqld: Can’t open file: ‘./dekmap_mybb/demo1_announcements.frm’ (errno: 24)

ใช้เช็คค่าในตารางดังกล่าว. ปัญหาแบบนี้มักเกิดจาก ลบตารางไปแล้วแต่ไม่ได้ลบไฟล์ .frm หรือ ในเคสนี้ไฟล์ .frm น่าจะหายไป. เช็คที่ตารางตาม log ครับแล้วปัญหาจะหาย

#4

ยังไม่ได้ลองเลยครับ แต่ล่าสุดลองเข้าไปตรวจสอบดูเมื่อสักครู่ ก็ดูท่าทางปกติดีครับ
ตอนเกิดปัญหาไม่ทันดูสักทีครับ มาตอนเผลอทู๊กกกที สงสัยต้องหาเวลา monitor ดูทั้งวันแล้วครับ

#5

ขอบคุณมากๆ ครับ เดี๋ยวขอไปลองไล่ดูก่อนครับ

#6

เครื่องทำ share host หรืออะไรครับ ถ้า share host(ขาย) ดูพวกเว็บบอร์ดลูกค้า มีใครปล่อยทิ้งหรือเปล่า เพราะ spam จะไป post แบบไม่ยั้งเลย

#7

ใช่เลยครับพี่ เพิ่งเข้าไปตรวจดูเจอตารางของลูกค้าใช้ SMF Board บวมไป 5GB แหนะครับ spam ทั้งนั้นเลย T_T แต่ไม่ทราบว่าตรงปัญหาหรือไม่ครับ อันนี้แจ้งลูกค้าไปแล้วครับ

#8

เปิด slow log แล้วไล่ดูครับ

#9

ขอถามด้วยความซื่อบื้อของผมจริงๆ ครับพี่ ลองไปหาข้อมูลเกี่ยวกับไไฟล์ frm แล้วอ่านไม่เข้าใจจริงๆ ครับ
ไฟล์ .frm ที่เป็นปัญหาของ ตารางนี้ ถูกเก็บไว้ที่ไหนเหรอครับ เราจะสามารถเข้าไปตรวจสอบได้ยังไงครับว่าไฟล์หายไป

ผมลองเข้าไปใน phpmyadmin แล้วเข้าไปตรวจสอบตารางดู

ก็ไม่ทราบจริงๆ ครับว่าจะดูปัญหาที่ไหน
ลองสั่ง database check ใน directadmin แล้ว สถานะของตารางนี้ขึ้น OK ครับ

รบกวนอีกครั้งครับพี่

#10

ดู slow log ได้จากตรงไหนเหรอครับ

ปกติผมจะดูความเคลื่อนไหวของ mysql จากการ
login ด้วย User : da_admin ไปที่ phpmyadmin แล้วคลิกที่ localhost แล้วคลิกที่ status ครับ
เพื่อดูฐานข้อมูลของทุก user ว่ามีของใครใช้ time เยอะๆ มั้ยครับ

สงสัยว่าจะคนละส่วนกัน

#11

แก้ my.cnf เติมตรงนี้เข้าไปใน section ของ [mysqld] ครับ

log_slow_queries = /var/log/mysql/mysql-slow.log
long_query_time = 1

เสร็จแล้วสร้างโฟลเดอกับเตรียม permission ให้เรียบร้อย

mkdir -p /var/log/mysql
chown mysql:adm /var/log/mysql

เสร็จแล้ว restart mysql ครับ

ถ้ารีแล้ว error ลองเปลี่ยนคำว่า log_slow_queries เป็น slow_query_log_file ดูครับ

#12

ขอบคุณมากๆ คร้าบ

#13

chown mysql:adm /var/log/mysql

น่าจะ

chown mysql:mysql /var/log/mysql

รึเปล่าครับ

ส่วนไฟล์ frm ก็ดูตาม path ที่ระบุใน error ครับ

#14

จริงด้วยครับ adm มัน group ของ debian ถ้าฝั่ง centos ผมไม่แน่ใจแฮะ น่าจะ mysql:mysql แหละครับ

#15

ได้ slow query log แล้วครับ ขอบคุณมากๆ ครับพี่
ได้ความรู้มากมายเลย งานนี้

:875328cc:

#16

Repair database ดูครับ

#17

Log มาแล้วครับพี่ Log นี้อ่านค่าอย่างไรเหรอครับ
หาก table ไหน query time มากกว่า 1.0 ขึ้นไปเท่ากับว่าเป็นการ query ที่นานผิดปกติใช่มั้ยครับ

Query_time
Lock_time
Rows_sent
Rows_examined

ของแต่ละ entry จะต้องไม่เกินเท่าไหร่เหรอครับ เราถึงเห็นสมควรจะต้องแจ้งลูกค้าครับ

รบกวนด้วยนะคร้าบ :875328cc:

/usr/sbin/mysqld, Version: 5.1.62-log (MySQL Community Server (GPL)). started with:
Tcp port: 0 Unix socket: (null)
Time Id Command Argument

Time: 121028 19:40:11

User@Host: sukanjak_class[sukanjak_class] @ localhost []

Query_time: 1.039068 Lock_time: 0.000037 Rows_sent: 27910 Rows_examined: 43189

use sukanjak_class;
SET timestamp=1351428011;
Select * from prakard Where (prakard.expire_date >= ‘2012-10-28’) OR (prakard.expire_date = ‘0000-00-00’);

Time: 121028 19:47:35

User@Host: sukanjak_class[sukanjak_class] @ localhost []

Query_time: 1.301609 Lock_time: 0.000033 Rows_sent: 32025 Rows_examined: 43190

SET timestamp=1351428455;
Select * from prakard Where province_id=‘01’;

User@Host: sukanjak_class[sukanjak_class] @ localhost []

Query_time: 1.132759 Lock_time: 0.000116 Rows_sent: 911 Rows_examined: 45927

SET timestamp=1351428455;
SELECT
prakard.prakard_id,
prakard.member_id,
prakard.title,
prakard.title_short,
prakard.price,
prakard.ptype_id,
prakard.state_id,
prakard.file1,
prakard.keyword1,
prakard.keyword2,
prakard.keyword3,
prakard.keyword4,
prakard.keyword5,
prakard.keyword6,
prakard.email,
prakard.fullname,
prakard.province_id,
prakard.read_count,
prakard.s_mud,
category.cate_name,
group.group_name,
province.province_name
FROM
prakard
INNER JOIN group ON (prakard.group_id = group.group_id)
INNER JOIN category ON (prakard.cate_id = category.cate_id)
INNER JOIN province ON (prakard.province_id = province.province_id)
WHERE
((prakard.expire_date >= ‘2012-10-28’) OR (prakard.expire_date = ‘0000-00-00’))
AND (prakard.group_id = ‘19’) AND (prakard.s_mud != ‘Y’)
ORDER BY
prakard.s_mud DESC,
prakard.modify_date DESC;

Time: 121028 19:48:26

User@Host: sukanjak_class[sukanjak_class] @ localhost []

Query_time: 1.428680 Lock_time: 0.000092 Rows_sent: 27911 Rows_examined: 43190

SET timestamp=1351428506;
Select * from prakard Where (prakard.expire_date >= ‘2012-10-28’) OR (prakard.expire_date = ‘0000-00-00’);

#18

ปกติผมจะเก็บ slowlog ไว้ที่เดียวกันกับ var/lib/mysql เลย จะได้ดูทั้ง log ที่เป็น slow และ log ที่เป็น error ของ hostname

และก็ไม่ต้อง chown ด้วย แต่ผลเสียของมันก็คือมันจะไม่เป็น group ฮาๆ

–

ไม่ทราบว่าระหว่างที่มีปัญหา ได้ลองดู iostat ของ hdd หรือเปล่าครับ

แล้วลองไปดู status ใน phpmyadmin ด้วยครับ ว่า config ที่ปรับลงไปสมเหตุสมผลกันหรือเปล่า

ดูจาก log แล้ว ยังไม่น่าห่วงเท่า case ผมเล๊ย 555

SELECT * FROM movie ORDER BY RAND() limit 56;

User@Host: admin_vanavat[admin_vanavat] @ localhost []

Query_time: 13.325276 Lock_time: 0.000046 Rows_sent: 56 Rows_examined: 8772

SET timestamp=1351092334;

suck query

#19

query ไม่มี index เลยซักกะตัว (สังเกตจาก rows_examined เยอะมาก) ทำ index ก็ช่วยได้ 90% ละครับ

#20

ตามบักไอซ์ฮะ ลืมทำ index กันนี่เอง จับใส่ index ก็น่าจะช่วยได้เยอะแล้ว

ถ้ายังอืดอยู่ลองเช็ค key buffer ว่าใหญ่พอรึเปล่า ลองรันพวก mysqltuner.pl ดูก็ได้ครับจะช่วยหาสาเหตุของปัญหาได้

ส่วนเรื่องที่เก็บ log นี่แล้วแต่ความชอบครับ อะไรที่เป็น log ผมจะพยายามให้ไปอยู่ใน /var/log เพราะ policy การ backup ไม่เหมือนกับใน /var/lib ครับ