2017年1月27日金曜日

シェルスクリプトで時刻をミリ秒まで出したい

シェルスクリプトで、ログの時刻をミリ秒まで出したい箇所があり、date コマンドでは出せないという思い込み (UNIXの古い経験) から、perl で小さなツール (gettimeofday を呼ぶ程度) を書きました。そして、いちおう動くようになった、そのあとに、date コマンドで出せることを知りました。orz
最初のリサーチは大事ですね。
[root@hoge tmp]# date +"%F %T 0.%3N" ; ./mydate.pl ; date +"%F %T 0.%3N" ; ./mydate.pl
2017-01-27 07:53:22 0.131
2017-01-27 07:53:22 0.133
2017-01-27 07:53:22 0.133
2017-01-27 07:53:22 0.135
[root@hoge tmp]# /usr/bin/time -v date +"%F %T 0.%3N"
2017-01-27 07:53:36 0.230
 Command being timed: "date +%F %T 0.%3N"
 User time (seconds): 0.00
 System time (seconds): 0.00
 Percent of CPU this job got: 93%
 Elapsed (wall clock) time (h:mm:ss or m:ss): 0:00.00
 Average shared text size (kbytes): 0
 Average unshared data size (kbytes): 0
 Average stack size (kbytes): 0
 Average total size (kbytes): 0
 Maximum resident set size (kbytes): 724
 Average resident set size (kbytes): 0
 Major (requiring I/O) page faults: 0
 Minor (reclaiming a frame) page faults: 228
 Voluntary context switches: 1
 Involuntary context switches: 1
 Swaps: 0
 File system inputs: 0
 File system outputs: 8
 Socket messages sent: 0
 Socket messages received: 0
 Signals delivered: 0
 Page size (bytes): 4096
 Exit status: 0
[root@hoge tmp]# /usr/bin/time -v ./mydate.pl 
2017-01-27 07:53:46 0.445
 Command being timed: "./mydate.pl"
 User time (seconds): 0.00
 System time (seconds): 0.00
 Percent of CPU this job got: 100%
 Elapsed (wall clock) time (h:mm:ss or m:ss): 0:00.00
 Average shared text size (kbytes): 0
 Average unshared data size (kbytes): 0
 Average stack size (kbytes): 0
 Average total size (kbytes): 0
 Maximum resident set size (kbytes): 2300
 Average resident set size (kbytes): 0
 Major (requiring I/O) page faults: 0
 Minor (reclaiming a frame) page faults: 634
 Voluntary context switches: 1
 Involuntary context switches: 1
 Swaps: 0
 File system inputs: 0
 File system outputs: 8
 Socket messages sent: 0
 Socket messages received: 0
 Signals delivered: 0
 Page size (bytes): 4096
 Exit status: 0
[root@hoge tmp]# time date +"%F %T 0.%3N"
2017-01-27 07:56:18 0.292

real 0m0.001s
user 0m0.000s
sys 0m0.001s
[root@hoge tmp]# time ./mydate.pl 
2017-01-27 07:56:30 0.545

real 0m0.002s
user 0m0.001s
sys 0m0.001s
[root@hoge tmp]# 
このように、当然、perl で書いたら重い (と言ったって2ミリくらいだけど) ですね。手持ちの新旧VM環境を調べたところ、現在の RHEL/CentOS系 (RHEL3 以降) なら %N を使えるようです。というわけで、せっかく書いた mydate.pl は、お蔵入り。

2017-02-02追記
お手軽に性能計測と言えば、昔から time コマンドを使ってましたが、最近は perf stat が使えるので、備忘録です。
time コマンドよりも精細な計測が出来るので、今回のように処理時間が極く短いモノを測る場合は、こちらを利用すると良いようです。
[root@hoge tmp]# perf stat ./mydate.pl 
2017-02-02 03:21:50 0.747

 Performance counter stats for './mydate.pl':

          1.504866      task-clock (msec)         #    0.886 CPUs utilized          
                 0      context-switches          #    0.000 K/sec                  
                 0      cpu-migrations            #    0.000 K/sec                  
               592      page-faults               #    0.393 M/sec                  
         4,952,896      cycles                    #    3.291 GHz                      (33.77%)
         2,461,931      stalled-cycles-frontend   #   49.71% frontend cycles idle   
         2,461,430      stalled-cycles-backend    #  49.70% backend cycles idle     
         4,000,101      instructions              #    0.81  insn per cycle         
                                                  #    0.62  stalled cycles per insn
           760,869      branches                  #  505.606 M/sec                  
            31,136      branch-misses             #    4.09% of all branches          (88.50%)

       0.001698771 seconds time elapsed

[root@hoge tmp]# perf stat date +"%F %T 0.%3N"
2017-02-02 03:39:52 0.612

 Performance counter stats for 'date +%F %T 0.%3N':

          0.355000      task-clock (msec)         #    0.658 CPUs utilized          
                 0      context-switches          #    0.000 K/sec                  
                 0      cpu-migrations            #    0.000 K/sec                  
               193      page-faults               #    0.544 M/sec                  
         1,193,873      cycles                    #    3.363 GHz                    
           800,322      stalled-cycles-frontend   #   67.04% frontend cycles idle   
           636,341      stalled-cycles-backend    #  53.30% backend cycles idle     
           785,182      instructions              #    0.66  insn per cycle         
                                                  #    1.02  stalled cycles per insn
           144,848      branches                  #  408.023 M/sec                  
           branch-misses                                               

       0.000539333 seconds time elapsed

[root@hoge tmp]# 
time コマンドによる計測では、mydate.pl は、date コマンドより2倍程度の重さに見えてましたが、perf stat で計ると、4倍程度重いという結果が見てとれました。

2017年1月20日金曜日

/var/log/cron に crond[xxxx]: (CRON) bad minute (/etc/cron.d/hoge.crontab) メッセージが出る

CentOS 7.3 で crontab を書いていて、/var/log/cron に謎のエラーが出て、しばし格闘したので備忘録です。
出力されたのは、次のメッセージです。
Jan 20 07:19:01 hoge crond[2587]: (CRON) bad minute (/etc/cron.d/hoge.crontab)
hoge.crontab の中身は、こちらです。例示のため、エッセンスに絞ってます。
OP=
30 7 * * * root [ -z "$OP" ] && true
実際に作成していた crontab は、もっと長いもので、どこに問題があるか分からず、徐々に削っていったら、OP= の行が原因とわかりました。おそらく、cronie に誤認されているものと思います。次のように書き換えたらエラー出なくなりました。
OP=""
30 7 * * * root [ -z "$OP" ] && true
やれやれ、こんなところで凝ったことをしようとしないほうが良いですね。

調査の過程で、次のページを参考にさせてもらいました。綺麗&上手にまとめてらっしゃるもんだなあと、感心してしまいました。
http://www.server-memo.net/tips/etc-crontab.html

ついでに、その他のハマりどころとして、環境変数 (例では OP=) の後半にコメント (#) は書けないという事を知りました。man 5 crontab に記述ありました。みなさまも、お気をつけください。

2017年1月18日水曜日

ロングオプションの罠

とある自作 bash スクリプトにて、fallocate コマンドを使ったのですが、これまた、とあるサーバで --length オプションがエラーに。。。
[root@hoge ~]# fallocate --keep-size --length 1m /tmp/fuga
fallocate: unrecognized option '--length'
Usage: fallocate [options] <filename>

Options:
 -h, --help          this help
 -n, --keep-size     don't modify the length of the file
 -p, --punch-hole    punch holes in the file
 -o, --offset   offset of the allocation, in bytes
 -l, --length   length of the allocation, in bytes

For more information see fallocate(1).
おかしい、他のサーバでは、大丈夫なのに。。。
CentOS 6 用の最新の util-linux-ng の .src.rpm を展開して、さぐってみたら、ありました typo バグ。
[root@hoge SOURCES]# cat util-linux-ng-2.17-opts-typos.patch 
diff -up util-linux-ng-2.17.2/misc-utils/findmnt.c.kzak util-linux-ng-2.17.2/misc-utils/findmnt.c
--- util-linux-ng-2.17.2/misc-utils/findmnt.c.kzak 2016-03-08 11:39:00.996400246 +0100
+++ util-linux-ng-2.17.2/misc-utils/findmnt.c 2016-03-08 11:44:49.598921954 +0100
@@ -586,7 +586,10 @@ int main(int argc, char *argv[])
      { "output",       1, 0, 'o' },
      { "raw",          0, 0, 'r' },
      { "types",        1, 0, 't' },
-     { "fsroot",       0, 0, 'v' },
+
+     { "nofsroot",     0, 0, 'v' },
+     { "fsroot",       0, 0, 'v' }, /* RHEL6: typo, backward compatibility */
+
      { "submounts",    0, 0, 'R' },
      { "source",       1, 0, 'S' },
      { "target",       1, 0, 'T' },
diff -up util-linux-ng-2.17.2/sys-utils/fallocate.c.kzak util-linux-ng-2.17.2/sys-utils/fallocate.c
--- util-linux-ng-2.17.2/sys-utils/fallocate.c.kzak 2016-03-08 11:39:01.028400021 +0100
+++ util-linux-ng-2.17.2/sys-utils/fallocate.c 2016-03-08 11:43:28.799496864 +0100
@@ -125,7 +125,10 @@ int main(int argc, char **argv)
      { "keep-size", 0, 0, 'n' },
      { "punch-hole", 0, 0, 'p' },
      { "offset",    1, 0, 'o' },
-     { "lenght",    1, 0, 'l' },
+
+     { "length",    1, 0, 'l' },
+     { "lenght",    1, 0, 'l' },  /* RHEL6: typo, backward compatibility */
+
      { NULL,        0, 0, 0 }
  };

[root@hoge SOURCES]# cat ../SPECS/util-linux-ng.spec
...
# 1122839 - fallocate and findmnt have wrong options according to man pages
Patch114: util-linux-ng-2.17-opts-typos.patch
...
* Mon Jan 11 2016 Karel Zak  2.17.2-12.19
...
- fix #1122839 - fallocate and findmnt have wrong options according to man pages
https://bugzilla.redhat.com/show_bug.cgi?id=1122839

というわけで、エラーが出ていたサーバの util-linux-ng が古かったというオチでした。やはり、ほとんどの場合、常に最新を使うのが吉ですね。もちろんです。

今回、--keep-size オプションを使おうとして、なんとなくロングオプションを選んでしまいましたが、こういった間違いが起きてる可能性を考えると、ショートオプションを使ったほうが吉かもしれませんね。自作スクリプトは、古い環境も対象にしているので、ショートオプションに修正しました。
人気ブログランキングへ にほんブログ村 IT技術ブログへ