เคยใหมครับ เมื่อใช้คำสั่ง dmesg เพื่อที่จะดู kernel message แล้วสงสัยว่า เวลาที่แสดงในเครื่องหมาย square bracket ที่อยู่ด้านหน้าของ message น่ะมันเป็นเวลาเท่าไหร่กันแน่?
อาจจะไม่บ่อยนัก แต่ผมก็เคยมีปัญหานั้น
ถ้าใช้คำสั่ง dmesg บน command line เราอาจจะเห็น message ประมาณนี้
[ 10.738140] udev[228]: starting version 164 [ 12.840798] ACPI: PCI Interrupt Link [LNKD] enabled at IRQ 9 [ 12.842168] PCI: setting IRQ 9 as level-triggered [ 12.843002] pci 0000:00:04.0: PCI INT A -> Link[LNKD] -> GSI 9 (level, low) -> IRQ 9 [ 12.856454] input: PC Speaker as /devices/platform/pcspkr/input/input2 [ 12.911121] vboxguest: major 0, IRQ 9, I/O port d020, MMIO at 00000000f0400000 (size 0x400000) [ 12.912531] vboxguest: Successfully loaded version 3.2.10_OSE (interface 0x00010004) [ 13.165633] piix4_smbus 0000:00:07.0: SMBus base address uninitialized - upgrade BIOS or use force_addr=0xaddr [ 13.233473] parport_pc 00:05: reported by Plug and Play ACPI [ 13.314410] ACPI: AC Adapter [AC] (on-line) [ 13.318154] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input3 [ 13.345820] ACPI: Power Button [PWRF] [ 13.376871] input: Sleep Button as /devices/LNXSYSTM:00/LNXSLPBN:00/input/input4 [ 13.420217] ACPI: Sleep Button [SLPF] [ 13.455000] input: ImExPS/2 Generic Explorer Mouse as /devices/platform/i8042/serio1/input/input5 [ 15.017345] Intel ICH 0000:00:05.0: PCI INT A -> Link[LNKA] -> GSI 5 (level, low) -> IRQ 5 [ 15.019308] Intel ICH 0000:00:05.0: setting latency timer to 64 [ 15.344130] intel8x0_measure_ac97_clock: measured 54439 usecs (10177 samples) [ 15.346177] intel8x0: measured clock 186943 rejected [ 15.704139] intel8x0_measure_ac97_clock: measured 55930 usecs (10470 samples) [ 15.705569] intel8x0: measured clock 187198 rejected [ 16.064125] intel8x0_measure_ac97_clock: measured 55919 usecs (10451 samples) [ 16.065415] intel8x0: measured clock 186895 rejected [ 16.066703] intel8x0: clocking to 48000 [ 17.234971] EXT3 FS on dm-0, internal journal [ 17.967548] loop: module loaded [ 23.754984] Adding 8388600k swap on /dev/mapper/lv-nilanont--swap. Priority:-1 extents:1 across:8388600k [ 30.580221] kjournald starting. Commit interval 5 seconds [ 30.581590] EXT3 FS on dm-2, internal journal [ 30.582599] EXT3-fs: mounted filesystem with ordered data mode. [ 31.094231] FAT: utf8 is not a recommended IO charset for FAT filesystems, filesystem will be case sensitive! [ 35.777014] e1000: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX [ 39.640499] fuse init (API version 7.13) [ 40.373844] binfmt_misc: Unknown symbol bprm_change_interp [ 40.469771] binfmt_misc: Unknown symbol bprm_change_interp [ 41.587335] vboxsf: Successfully loaded version 3.2.10_OSE (interface 0x00010004) [ 52.668229] lp: driver loaded but no devices found [ 52.742090] ppdev: user-space parallel port driver [ 64.384194] device eth0 entered promiscuous mode [ 66.379973] device eth0 left promiscuous mode [ 73.139965] tun: Universal TUN/TAP device driver, 1.6 [ 73.141787] tun: (C) 1999-2004 Max Krasnyansky <maxk@qualcomm.com>
ตัวเลขที่อยู่ภายใน [ ] เช่น “[ 73.141787]” ในบรรทัดสุดท้าย 73.141787 หมายความว่า ข้อความของ kernel ในบรรทัดนั้น
tun: (C) 1999-2004 ...
พิมพ์ออกมาหลังจากเครื่องเริ่มต้นทำงานไปแล้วประมาณ 17 วินาทีกับอีกนิดหน่อย 141787 ที่อยู่ข้างหลัง จะแสดงเวลาที่เป็นหน่วยย่อยในระดับ micro-second
ซึ่งการแสดงผลแบบนี้ จะไม่มีปัญหาซักเท่าไหร่ สำหรับเครื่องที่เพิ่งเปิดขึ้นมาใหม่ๆ เช่นเครื่อง desktop หรือ notebook ทั่วไป แต่สำหรับเครื่องที่ทำงานเป็น Server ซึ่งเปิดทิ้งเอาไว้เป็นชั่วนาตาปี, โขง, ชี, มูล, ปิง, วัง, ยม, น่าน นั้น บางทีเวลาเราใช้คำสั่ง dmesg ออกมา อาจจะเห็นเป็น message แบบนี้
... [201089.204812] br0: topology change detected, propagating [201089.204815] br0: port 1(eth0) entering forwarding state [201089.204838] br0: port 1(eth0) entering forwarding state [237531.522878] br0: port 1(eth0) entering forwarding state [237531.671857] r8169 0000:02:00.0: eth0: link down [237531.671888] r8169 0000:02:00.0: eth0: link down ...
จะเห็นว่าบรรทัด “br0: port 1(eth0) enter forwarding state” ในสองบรรทัดแรก กับบรรทัดที่สาม จะเกิดห่างกันพอสมควร ระยะเวลาห่างกันเท่าไหร่ เป็นเวลากี่วินาที ก็เอาตัวเลขทั้งสองตัวมาหักลบกันได้ ยุ่งยากนิดหน่อย แต่ก็ไม่มากจนเกินไป
แต่ปัญหาที่เกิดขึ้นก็คือ หลายครั้ง ผมอยากจะรู้ว่า “มันเกิดขึ้นเมื่อไหร่?” มากกว่า ที่อยากจะรู้ว่า “มันเกิดขึ้นหลังจากครั้งที่แล้วนานเท่าไหร่?”
อืม แล้วถ้าเป็นอย่างนั้นผมจะหาคำตอบได้ยังไง?
เนื่องจากเวลาที่คำสั่ง dmesg แสดงออกมา เป็นเวลานับเป็นจำนวนวินาที นับตั้งแต่เครื่องเริ่มต้นทำงาน เพราะฉะนั้น ถ้าเรา “รู้” ว่าเราเริ่มเปิดเครื่องเมื่อไหร่ เราก็สามารถ ใช้เวลานั้นเป็นเวลาตั้งต้น แล้วบวกเวลาด้วยจำนวนวินาทีที่ผ่านไป แล้วค่อยแปลงเวลานั่นกลับมาเป็นวันเดือนปีอีกครั้ง เราก็จะรู้เวลาที่เกิดเหตุการณ์นั้นขึ้นใช่ใหมครับ
ฟังดูไม่ยาก … รึเปล่า?
เวลาที่เครื่องเริ่มต้นทำงานเราจะเอามันมาจากใหนได้บ้างล่ะนี่?
ถ้าเครื่องของเราเพิ่ง reboot มาเมื่อไม่นานเท่าไหร่ เราอาจจะใช้คำสั่ง last ในการหาเวลา boot ของเครื่องได้โดยประมาณแบบนี้
$ last | grep reboot reboot system boot 3.2.0-4-amd64 Tue Mar 19 18:14 - 02:25 (6+08:10)
อืม … เครื่องของผมเพิ่ง reboot ไปเมื่อวันที่ 19 มีค. เวลา 18:14 และ เวลาขณะที่เขียนบันทึกฉบับนี้ เวลาผ่านไปแล้ว 6 วัน 8 ชม. กับอีก 10 นาที … แต่ว่า วิธีการนี้จะมีปัญหากับเครื่อง boot มาแล้วตั้งแต่เดือนที่แล้ว หรือ นานกว่านั้น เพราะ /var/log/wtmp จะเก็บข้อมูลเฉพาะเดือนนี้ และ โดยทั่วไปแล้วจะมีข้อมูลเก็บย้อนหลังอีกแค่ 1 เดือนเท่านั้น (สำหรับ server ที่ผมดูแลอยู่ ข้อมูลของ wtmp จะระบุใน logrotate config ให้เก็บย้อนหลังไปอย่างน้อย 12 เดือน) … ไม่ว่าอย่างไร วิธีการนี้จะมีปัญหาถ้าต้องการที่จะได้ข้อมูลที่ถูกต้องแน่นอนทุกครั้ง
งั้นมีวิธีใหนอีกบ้าง? คำสั่ง uptime ล่ะ
$ uptime 02:31:56 up 6 days, 8:17, 23 users, load average: 1.00, 0.98, 0.95
แต่ … เอ วิธีการนี้เราจะได้มาแค่ ระยะเวลาที่เครื่องทำงานอยู่เท่านั้นนี่นา ไม่ได้บอกว่าเครื่อง ‘เริ่ม’ ทำงานเมื่อไหร่ … ใช่ใหม?
ใช่แล้วครับ! แต่เรามีคำสั่งที่จะช่วยอีก 1 คำสั่งคือคำสั่ง date
$ date;uptime Tue Mar 26 02:33:05 ICT 2013 02:33:05 up 6 days, 8:18, 23 users, load average: 0.85, 0.95, 0.94
เอาล่ะ คราวนี้ เราได้เวลา ‘ขณะนี้’ ของเครื่องออกมาแล้ว จากคำสั่ง date และเราได้ ‘ระยะเวลาที่เครื่องทำงาน’ มาจากคำสั่ง uptime เพราะฉะนั้น ถ้าผมนับย้อนหลังจากเวลา ‘ขณะนี้’ ไปเท่ากับเวลา ‘uptime’ ผมก็จะได้เวลาที่เครืองเริ่มต้นทำงานขึ้นมา … ใช่ใหมครับ
start_time = "Tue Mar 26 02:33:05 ICT 2013" - "6 days, 8:18"
เอ่อ … จะง่ายไปใหมเนี่ย เอามันมาลบได้อย่างนั้นน่ะ? ถ้าทำอย่างได้จริง ชีวิตของ sysadmin ก็คงง่ายขึ้นครับ แต่ชีวิตจริงของ admin มันไม่ง่ายดายขนาดนั้น
แต่ถ้าจะให้ผมแปลง string ของวันที่กลับมาเป็นตัวเลข และแปลง string ของระยะเวลา กลับมาเป็นตัวเลข โดยใช้ shell script เองก็คงไม่ไหวเหมือนกันแหละครับ 🙂
บน unix เรามี tools ซึ่งช่วยในการจัดการเรื่อง วัน/เวลาอยู่แล้ว คำสั่งนั้นก็คือ คำสั่ง date เพื่อนเก่าของเราน่ะเอง
ถ้าเราใช้คำสั่งนี้แบบธรรมดา เราก็จะได้ string ของ ข้อความที่เป็นแบบที่เรียกว่า human readable date string ออกมาตามตัวอย่าง เราสามารถระบุให้คำสั่ง date แสดงข้อความออกมาเป็นรูปแบบอื่นๆได้อีกด้วย เช่น แสดงเวลานับเป็นวินาทีเริ่มจาก เวลาอ้างอิงของระบบปฏิบัติการแบบ unix ที่เรียกกันโดยทั่วไปว่า epoch ซึ่งเวลาที่ว่านั่นก็คือ 1970-01-01 00:00:00 … ถ้าจะถาม ว่าทำไมเวลาอ้างอิง หรือ epoch ถึงต้องเป็นวัน/เวลานี้ด้วย คำตอบคงจะต้องเท้าความถึงประวัติศาสตร์ของ Unix ค่อนข้างไกล … ซึ่งคงจะออกนอกเรื่องไปอีกพอสมควร เพราะฉะนั้นขอละไว้เพียงแค่นี้ก่อนก็แล้วกันครับ ผู้ที่สนใจลองหาอ่านเองโดยใช้ google ช่วยได้ครับ
คำสั่ง date สามารถแสดงผลออกมาได้หลากหลายรูปแบบมาก รายละเอียดสามารถอ่านได้จาก man page ของคำสั่ง date นะครับ แต่สำหรับกรณีของการแสดงเวลาเป็นวินาทีนับจากเวลาอ้างอิง ก็สามารถใช้คำสั่ง
date +%s
รูปแบบ +%… จะเป็นการกำหนดรูปแบบการแสดงผล นะครับ ตัวอย่างเช่น บนเครื่องของผมขณะที่เขียนบันทึกอยู่ขณะนี้
$ date;date +%s Tue Mar 26 02:50:49 ICT 2013 1364241049
เวลา 1364241049 วินาทีนับจาก epoch ก็เป็นเวลาเดียวกันกับ Tue Mar 26 02:50:49 ICT 2013 เพียงแต่แสดงในรูปแบบที่ต่างกัน
เอาล่ะเราได้เวลาที่เป็น เวลาปัจจุบัน แสดงออกมาเป็นวินาทีแล้ว … แล้วทีนี้ ค่าเวลา uptime ล่ะ เราจะแปลง “6 days, 8:18” หรือ 6 วัน 8 ชม. 18 นาที มาเป็นตัวเลขวินาทียังไง … ดูแล้วก็น่าจะไม่ยากมากเท่าไหร่ … แต่ก็ไม่ง่าย …(ฮา)
จริงๆแล้ว ก็มีวิธีง่ายๆอยู่ครับ ค่าของ uptime เราสามารถอ่านมาจากไฟล์ /proc/uptime ได้ โดยไม่ต้องไปแปลงจาก string ของ “N days, HH:MM” โดยตรง
$ cat /proc/uptime 549627.40 1106209.61
ตัวเลขตัวแรกเป็น uptime ส่วนตัวที่สองเป็น cpu idle time
เอ๊ะ.. ทำไม idle time ถึงมากกว่า uptime ล่ะ? … คือว่าเครื่องที่ผมใช้งานอยู่มันมี core ของ processor อยู่จำนวน 4 core ใน 1 cpu น่ะครับ ค่า idle time นับของ cpu ทุกตัวรวมกัน ตัวเลขก็เลยออกมาสูงกว่า cpu uptime
เอาล่ะ เราสามารถ หาวัน/เวลา ที่เครื่องเริ่มต้นทำงานได้ โดยการใช้คำสั่งของ shell ได้คร่าวๆประมาณนี้ครับ
NOW=`date +%s` UPTIME=`cat /proc/uptime | cut -f1 -d.` STARTTIME=`expr $NOW - $UPTIME` echo $STARTTIME
เวลาของ UPTIME เราใช้เฉพาะหน่วยวินาทีโดยการใช้ จุดเป็นตัวคั่น แล้วตัดส่วนที่เหลือทิ้งไปทั้งหมด (รวมทั้ง idle time ด้วย) ส่วนการคำนวณ ก็ใช้คำสั่ง expr เป็นตัวช่วย
แต่เวลาที่ได้เป็นตัวเลข จำนวนเป็นวินาทีนี่!! ดูไปก็ยังไม่รู้ว่ามันเป็นวัน/เวลาใหนกันแน่ … จะต้องแปลงตัวเลขกลับยังไงนี่
ตรงนี้ไม่ยากครับ ใช้คำสั่ง date อีกนั่นแหละ เราสามารถใช้ option -d หรือ –date= สำหรับการระบุเวลาที่ต้องการเป็นเวลาอื่น แทนที่จะเป็นเวลา “ปัจจุบัน” ได้ โดยที่ ถ้าเราจะระบุเวลาเป็น จำนวนวินาทีนับจากเวลาอ้างอิง — epoch ก็ให้ใส่เครื่องหมาย @ หน้าตัวเลขนั้นครับ ซึ่ง สามารถลองได้ประมาณนี้
$ date -d @0 Thu Jan 1 07:00:00 ICT 1970 $ date -d @1363691682 Tue Mar 19 18:14:42 ICT 2013
ถ้าใช้ @0 นั่นก็คือระบุเวลาอ้างอิงเลย ก็จะได้เป็นวันที่ 1 มค. 1970 เวลา 00:00:00 UTC — เวลาที่แสดงเป็น 07:00:00 ICT ซึ่งเป็นเวลาของประเทศไทย (=GMT+7) และ เวลาที่เครื่องคอมพิวเตอร์ที่ผมใช้ reboot ครั้งสุดท้ายเมื่อ วันที่ 19 มีค. เวลา 18:14 น.
ส่วนที่เหลือก็คือ รับข้อมูลแต่ละบรรทัดจาก คำสั่ง dmesg เข้ามาแล้วก็แปลงข้อมูลของ time stamp ที่อยู่ในรูปแบบ uptime ซึ่งอยู่ระหว่างเครื่องหมาย [] ข้างหน้าออกมา ส่วนนี้ สามารถใช้คำสั่ง read ช่วย เช่น dmesg บรรทัดสุดท้ายได้ข้อมูลออกมาเป็น
$ dmesg | tail -1 [288163.997319] br0: port 1(eth0) entering forwarding state
คำสั่ง read จะอ่านค่ามาเก็บไว้ในตัวแปร โดยจะแบ่งโดยใช้ space
$ dmesg | tail -1 | (read STAMP REST; echo "STAMP=$STAMP REST=$REST") STAMP=[288163.997319] REST=br0: port 1(eth0) entering forwarding state
ในกรณีนี้ เราจะได้ค่าเวลา ซึ่งมี เครื่องหมาย [] คร่อม อยู่ในตัวแปร shell ชื่อ STAMP และ ส่วนที่เหลือทั้งหมด จะอยู่ในตัวแปร shell ที่ชื่อว่า REST
ในส่วนของ เวลา อาจจะอยู่ในรูปแบบ [ 0.00000] ก็ได้ ซึ่งจะมีช่องว่างอยู่หลัง ‘[‘ และก่อนตัวเลข ซึ่งสามารถกำจัดทิ้งได้ ด้วยคำสั่ง sed และ เครื่องหมาย ‘]’ ด้านหลังตัวเลขก็จะสามารถตัดทิ้งได้ด้วย sed เช่นเดียวกัน หรือ อาจจะใช้คำสั่ง tr ด้วย option -d ก็ได้
ตัวเลขที่ได้ ตัดเอามาเฉพาะส่วนที่เป็นวินาที แล้วเอามาบวกกับค่า STARTTIME โดยใช้คำสั่ง expr เป็นตัวช่วยเหมือนเดิม
เอาล่ะ ใช้สิ่งที่ได้เรียนรู้จากข้างต้น เราก็จะสามารถเขียนเป็น shell script ออกมาได้ประมาณนี้
#!/bin/sh
DSTR1="+%b %d %H:%M:%S" # Syslog format Month Date Hour:Min:Sec
DSTR2="+%Y-%m-%d %H:%M:%S" # ISO format
NOW=`date +%s` # current timestamp in second
UPTIME=`cat /proc/uptime | cut -f1 -d.` # current uptime
START=`expr $NOW - $UPTIME # start time of this machine
cat - | sed 's/^\[ *//' |\
while read STAMP REST; do
SEC=`echo $STAMP | tr -d '[]' | cut -f1 -d.`
TIME=`expr $START + $SEC`
DATE=`date -d @$TIME "$DSTR1"`
echo "$DATE $REST"
done
ส่วนที่เพิ่มขึ้นมาก็คือ การเลือกแสดงผล ออกมาเป้นรูปแบบเดียวกับ date/time stamp ที่ใช้ใน log file (DSTR1) หรือ จะใช้แบบ ISO format (DSTR2)
วิธีการใช้งาน script ตัวนี้ ซึ่งสมมติให้มีชื่อว่า dmesg-datestamp ก็ใช้แบบนี้ครับ
$ dmesg | ./dmesg-datestamp
ซึ่งในกรณีที่มี ข้อความใน dmesg จำนวนมาก ก็อาจจะใช้เวลาค่อนข้างนานเพราะในแต่ละบรรทัด ของ dmesg จะต้องมีการคำนวณ เวลาและแปลงเป็นวันที่ใหม่ โดยการใช้คำสั่ง expr และ date ตามลำดับ ซึ่งสามารถลดเวลาที่ใช้ในการแสดงผล โดยเลือกเอาเฉพาะ dmesg ในบรรทัดที่เราสนใจได้ เช่น
$ dmesg | grep eth0 | ./dmesg-datestamp
หรืออาจจะ redirection ลงไปเก็บไว้ในไฟล์ แล้วอ่านจากไฟล์ แทนที่จะอ่านจากคำสั่ง dmesg ทุกครั้ง
สำหรับคนที่ ทนอ่านมาจนถึงบรรทัดนี้ แล้วกำลังจะบอกผมว่า … จริงๆแล้ว ไม่ต้องทำถึงขนาดนั้นก็ได้ครับ คำสั่ง /bin/dmesg มี option -T ซึ่ง สามารถแปลง time stamp ให้อยู่ในรูปแบบ human readable ให้อยู่แล้วโดยไม่จำเป็นจะต้องพึ่งพา shell script ใดๆเลย
…
แหะๆ ครับ 
ผมก็ทราบแล้วครับ … แต่ว่านั่นมันหลังจากผมเขียน script เสร็จแล้ว (ฮา)
บน Debian Linux ถ้าใช้ wheezy ก็จะสามารถใช้
$ dmesg -T
ได้เลย แต่บน Debian squeeze ซึ่งเป็น stable release ของ Debian ในตอนนี้ คำสั่ง dmesg ยังไม่สามารถใช้งาน option -T ได้ แต่ปัญหานี้ก็คงมีอีกไม่นานเท่าไหร่ เพราะ wheezy กำลังจะกลายเป็น stable release ในของ Debian ภายในไม่ช้า …
แต่ … จะทำยังไงได้ล่ะ ก็เขียนไปแล้วนี่ …
ส่วนใครที่อ่านมาจนถึงบรรทัดนี้แล้ว … ก็อ่านไปแล้วนี่ ช่วยอะไรไม่ได้เนอะ …
ขอจบเอาดื้อๆแค่นี้แหละคร้าบ …