Grafana & Graphite でRADIUSのログを可視化してみた 開発編

ネットワーク プログラミング

このエントリは「Grafana & Graphite でRADIUSのログを可視化してみた 概要編」の続きとなります。最初のエントリをご覧になってからお読みください。

miyalog.hatenablog.jp

さてこちらが本編。RADIUS認証ログ可視化ツール Radtail の開発にあたり、苦労した点、工夫した点を語らせて頂きます。

  • tail -f でログあつめ
  • マルチプロセス導入への道のり
    • Graphite データ上書き問題
    • そしてマルチプロセスへ
  • defaultdict で簡単集計
  • パフォーマンスチューニング
    • ベンチマークで現状把握
    • プロファイリングで原因特定
    • datetime.strptime 対策
    • multiprocessing.Queue 対策
    • チューニングの効果
  • Graphite 書き込み間に合わない問題
  • おわりに
続きを読む

Grafana & Graphite でRADIUSのログを可視化してみた 概要編

ネットワーク プログラミング

NetOpsCoding Advent Calendar 2016 @ Qiita 12/6 のエントリです。サービスの異常を素早く一目で把握できるよう、RADIUSサーバーのログを可視化するツールを作ったお話をします。

きっかけ

おはようございます！(午後6時)　とある通信会社の委託でネットワークの監視業務をしている夜勤作業員です。（エンジニアじゃないよ）

f:id:miyahan:20161104004823p:plain

具体的にはこんな感じのCiscoの古い教科書によく載っているようなインターネットには直接繋がっていないネットワーク（いわゆる閉鎖網）を見ているのですが、サービスの正常性を確認する方法として、各ルーターにTelnetし show pppoe session といったコマンドを叩いて、お客様のPPPoEセッションやLAC〜LNS間のL2TPトンネルが確立しているかをチェックします。ただこの作業は、

  • 障害の影響が広いときに何十台ものLAC/LNSを確認するのが辛い
  • 機種によってはCPUが弱く、コマンドの結果が表示されるまで数分待たされて辛い
  • コマンドではその時点の状態しか確認できず、切れたセッションなどが見えず辛い
  • 目grep辛い、というか無理

などなど多くの難点を抱えており、確認作業が大幅に遅れたり、見落としによるヒューマンエラーを起こしお客様からクレームを受けるなど問題が山積みでした。

過去にルーターに自動でログインしコマンドを叩き、結果をいい感じにグラフィカルに表示するWebアプリを作ってそれなりの効果があったのですが、大きな障害では結局ツールをルータの台数分実行しなければいけなかったり、ルーターのCUIが遅い問題は如何ともし難く即時性に欠けるなど課題が残っていました。

そこでRADIUSサーバーの認証ログ・接続ログを使えないか？思い立ち、サービスの異常を素早く一目で把握すべく、ログを可視化するツール、名付けて「Radtail」（ラドテイル）を作ってみました。

Radtail 概要

ところで、先日行われた NetOpsCoding#3 で、日本Microsoft 北島さんの発表、Monitoring Intelligence に感銘を受け、それからというもの Grafana + Graphite をいじくり回しています。

www.slideshare.net

そんなわけで今回、データの収集・解析を自作の Python スクリプトで行いつつ、データの蓄積・描写にここぞとばかりと Graphite・Grafana を採用しました。

f:id:miyahan:20161116185907p:plainRadtail システム構成図

本ツールはマルチプロセス構成になっており、親プロセスである Control process、ログを収集する Collect process (サーバー台数分起動)、ログを集約・集計し Graphite に送信する Aggregate process が動作しています。

おおまかな流れは次の通りです

  1. RADIUSサーバーにSSHし、tail -F コマンドでログをリアルタイムに出力させる
  2. 出力されたログをパースし、さらにIPアドレスの逆引き等を行いデータを補完する
  3. データを Aggregate process のキューへ送信する
  4. キューバッファからデータを取り出し集計する
  5. 10秒ごとにデータを Graphite に送信する

なおツールは Supervisord を使ってデーモン化しています。

その結果を Grafana で描写させるとこうなります。いまのところ認証ログ(Access Accept / Reject)および、接続ログ(Accounting Start / Stop)を取り扱っています。

f:id:miyahan:20161104002147p:plain

いや～もう、こんなかっちょいいグラフが出るだけで既に大満足です。

サービス障害の見え方

ではこのツールでサービス障害はどのように見えるのでしょうか

LAGサイレント故障

LAC 〜 配下のL2スイッチ間は ACT - SBY モードのリンクアグリゲーションで構成しており、障害検出時に SBY 側に切り替わるようになっています。しかしログやコマンド上では正常に見えるのに、実はフレーム転送できていないというサイレント故障が起きることがまれによくあります。この事象が ACT 側で起きると、全てのパケットが故障した ACT 側に吸い込まれて二度と出てこないというブラックホール状態に陥り、当然お客様は通信できなくなってしまいます。

ツール試運用中にちょうどこの事象が起きたので、その際のスクリーンショットをご紹介します。

f:id:miyahan:20161116202127p:plainf:id:miyahan:20161116202130p:plain LAC全体のグラフ と 該当LAGのみにフィルタしたグラフ

5:14 から接続要求がゼロになっているので、ここから障害が発生したもとの推測されます。その5分後、5:19 にPPPのキープアライブタイムアウトが発生し切断処理が行われています。その後、関連部署からの連絡で障害を認知し、5:41 に保守者がLAGのアクティブポートを手動切り替えしサービスが回復しています。

もし Graphite のデータを定期的にチェックしアラートを出す手段を確立できれば、このようなサイレント故障をお客様や関連部門からのクレームではなく、監視部門が先に発見し対処することが出来るかもしれません。

ラインカード自己診断NG発生/回復

配下のL2スイッチでラインカードの自己診断NGのアラートが出て、数分後に自然回復するということがよくあります。この手のアラートは、主信号（お客様の通信）に影響がある場合と無い場合があり、もし影響があった場合は速やかにお客様に対しサービス中断発生の連絡をしなければなりません。つまり、なるべく早くサービス影響の有無を判断する必要があります。

サービス中断がある場合のグラフを示します

f:id:miyahan:20161116205432p:plain

アラートは 18:57 に発生しました。その瞬間から接続・切断処理が途絶えており、通信に影響があると判断できます。その後アラートは 18:59 に消えました。グラフを見ると 18:59:20 頃からお客様からの再接続要求が来て、切断と接続のイベント数がスパイクしています。

もしこれがコマンドによる確認だと、18:59:20 以降にお客様のPPPセッションが張り直されるまでサービス中断に気づくことができません。冒頭で述べた CLI が遅いルーターの場合はコマンドの結果が全て表示されるまで5分程度かかるため、障害発見まで10分を要してしまいます。

つまりこのツールを使うことで、サービス中断の確認作業が10分から10秒に短縮できるのです！

天災・広域停電

f:id:miyahan:20161124172629p:plain

2016年11月22日 5時59分、福島県沖で最大震度5弱の地震が起き、各地で停電・瞬低が発生しましたが、今回作ったツールがこの影響をとらえました。地震発生から5分後の 6:04 に一気にタイムアウトによる切断処理が起きています。その後ちょろちょろと再接続されていき、15分ほどで平常通りに戻っています。

これはうまく使えば広域障害の検出・把握に使えそうですね。ただ現状だとサーバーが非力で、このグラフを出すのに3分もかかってしまうのが課題です･･･。

まとめ

  • グラフ化することで状況を "点" ではなく "線" で捉えることができ、直感的に異常が起きたことを把握できる
  • タイムアウトによるセッション切断を待つこと無く、接続・切断要求が途絶えることで異常に気づくことができる

今後の展望

今回ログをリアルタイムに処理し可視化することで、サービスの提供状況を簡単に・素早く・確実に把握できることがわかりました。ただそれは保守者が能動的にダッシュボードを開かなければならず、サイレント故障に対しては全くの無力です。

現在、異常の自動検出の方法を模索中です。Grafana で「ヤバいホスト Top 10」みたいなダッシュボードを作ってみても良いでしょうし、別にスクリプトを定期的に走らせて Graphite の API を叩いてデータを取り出して精査してアラートを出すのも良いかもしれません。

一番の問題はどうやって異常と判断するかです。数分〜十分単位の起伏があるうえ、1日の生活変動（朝7時頃に起床、午後7時頃に帰宅により増える）や曜日変動（休日は家に居るので変動が少ない）があり一概にしきい値や変動率を適用できません。このへん学問的な話になってくるので勉強が必要ですね。

なんだか業務改善事例の発表ようになってしまいましたが、最も語りたかったのは開発の苦労話で、後半エントリで述べています。ぜひ引き継ぎご覧ください。

miyalog.hatenablog.jp

Graphite のチューニングには札束しかなかった話

プログラミング

ネタバレ：SSDにしろ、以上。

そしてややネタエントリーです。

  • いきさつ
  • 速さが足りない！！
  • いいからチューニングだ！！
    • MAX_CACHE_SIZE
    • MAX_UPDATES_PER_SECOND
    • MAX_CREATES_PER_MINUTE
    • CACHE_WRITE_STRATEGY
    • WHISPER_AUTOFLUSH
    • WHISPER_SPARSE_CREATE / WHISPER_FALLOCATE_CREATE
    • WHISPER_LOCK_WRITES
    • WHISPER_FADVISE_RANDOM
  • 何の成果も得られませんでしたぁ！
    • SSDの場合
    • HDDの場合
  • 力こそパワー！
  • 余談：SSDなんですぐ死んでしまうん？
    • SSD TBW 比較

いきさつ

会社でRADIUSサーバーの認証ログを Grafana + Graphite で可視化するツールを作っていまして、開発版を会社の本番サーバーにデプロイしたところ、起動してから数分経つとデータが記録・表示されなくなる不具合が起きました。

サーバーから収集しているログをダンプしてみたり、Graphiteに送るデータをダンプしてみたり、いろいろデバッグしてみたものの原因がわからず途方に暮れてたのですが、結果的に Graphite の統計情報を見ることで原因が判明しました。その大活躍したダッシュボードがコチラ！

f:id:miyahan:20161111225731p:plain開発環境 (Fedora 24 on VirtualBox / 作業用Windows PC)

f:id:miyahan:20161111225746p:plain本番環境 (CentOS 6 on VMware vSphere Hypervisor / ブレードサーバー)

なんと本番環境ではメモリ使用量やキャッシュサイズがどんどん肥大し続けています！ちなみにこのまま放置したところ、そのうち過負荷でダッシュボードにデータがプロットされなくなり、最終的には carbon-cache が OOM killer 先生によって友愛されました。

なお、Graphite の統計情報・上記ダッシュボードについては関連エントリで詳しく述べています。

それにしてもダッシュボードを作ってる最中にダッシュボードの有用性を思い知るとは。いやはや。

速さが足りない！！

f:id:miyahan:20161117210602p:plain

よくよくダッシュボードを見てみると、受信したデータポイント(metricsReceived : 緑色) に対し、ディスク書き込んだデータポイント(committedPoints : 黄色) が大幅に少ないことがわかります。そう、ディスクへの書き込みが全く間に合っていないのです。書き込み回数 (updateOperations : 水色) を見てください。虫の息です・・・。

開発用PC VM 本番サーバー VM
ホストOS VirtualBox @ Windows 7 VMware vSphere Hypervisor
ゲストOS Fedora 24 CentOS 6.8
CPU / 割り当て 低電圧Core-i5 2GHz / 2core Xeon E7 2.4GHz / 8core
RAM割り当て 4GB 4GB
ストレージ SATA SSD SAS 10krpm HDD x2 RAID1

ではなぜ本番サーバーだけ書き込みが間に合っていないのでしょうか。最も考えられるのはストレージの違い。でもいくらHDDとはいえ、エンタープライズ向けの1万回転 SAS HDDです。いまどきディスクI/Oが間に合わずシステムが落ちるなんて起こりうるのでしょうか･･･？fio というツールでベンチマークを取ってみました。

f:id:miyahan:20161117214239p:plain

f:id:miyahan:20161117214641p:plain

ベタな結果ではありますが、HDDはシーケンシャルアクセスはそこそこなものの、ランダムアクセスがダメダメです。

f:id:miyahan:20161117215738p:plain

The Architecture of Open Source Applications: Graphite より

Graphite が採用する Whisper はファイルベースのデータベースで、１メトリック＝１ファイルというシンプルな構成になっており、先頭のヘッダを読み込んで、その内容に基づき目的のデータポイントを読み書きしています。すなわち細かいリード/ライトが大量に走るということです。

上記ベンチマークでは、"Multi Random R/W" が最もその状況に近いでしょう。SSDパソコンは6000IOPS に対し、HDDサーバーは500IOPS･･･。これはたしかに書き込み間に合わないかも。SSDがこのくらい速いのは分かるのですが、本番サーバーの1MB/sってなんだよ、数年前の低価格パソコンかよ･･･。エンタープライズ 10krpm SAS ってなんだったんだよ･･･。

f:id:miyahan:20161117221814p:plain

続きを読む

Graphite / Carbon の統計情報を読み解く

プログラミング

f:id:miyahan:20161116181011p:plain

Graphite の データ記録を担う Carbon には自身の統計情報を自身のデータベースに記録する機能があります。以前パフォーマンス問題の調査のためにこれを使ったのですが、各パラメーターが何を意味しているのか、ドキュメントを探したものの見つからず苦労しました。

そこで、記録された実データや、設定変更に伴う挙動から「たぶんこうだろう」と思うところをメモとして残しておきます。もしお役に立てば幸いです。また、公式ドキュメントのありかや有用な情報をご存じの方、誤りを見つけた場合はぜひコメントください。

  • Carbon statistics の設定
  • cpuUsage / memUsage
  • avgUpdateTime
  • metricsReceived / committedPoints
  • updateOperations / pointsPerUpdate
  • cache.queues / cache.size
  • cache.queries

Carbon statistics の設定

この機能はデフォルトでONになっているので、何をしなくてもすぐ使えます。ちなみに /etc/carbon/carbon.conf で明示的に設定することができます。

# By default, Carbon itself will log statistics (such as a count,
# metricsReceived) with the top level prefix of 'Carbon' at an interval of 60
# seconds. Set CARBON_METRIC_INTERVAL to 0 to disable instrumentation
CARBON_METRIC_PREFIX = carbon  # デフォルトでは carbon.**** のメトリックで記録される
CARBON_METRIC_INTERVAL = 60  # デフォルトでは60秒間隔で記録される

初期設定ではログを90日間保存するようになっています。これを変更する場合は /etc/carbon/storage-schema.conf を編集してからデータベースを再構築してください。

[carbon]
pattern = ^carbon\.
retentions = 60:90d
続きを読む

VirtualBox のストレージは本当に遅いのか？ vs VMware Fusion

コンピューター プログラミング

ネットをただよっていると、VirtualBox のディスクは VMware と比べて数倍遅いとか、いやいや固定ディスクにすると速いとか、いろんな意見が出てきます。最近、高いI/Oスループットが必要なツールを作っていることもあり、興味が出たのでベンチマークを取ってみました。

測定条件

  • ベンチマークソフト : fio 2.x
  • 各テストケースを5回実行し中央値を採用
  • 測定マシン: Mac Pro mid 2010
    • OS : macOS Sierra
    • RAM: 20GB
    • Disk : crucial M550 (ただしSATA2.0接続) (システムディスク兼用)
  • VMware : Mac 上で動作する VMware Fusion 8.5 で測定
    • CPU : 4コア
    • RAM : 4GB
    • 仮想ディスク : 32GB
      • ディスク関連の設定はデフォルト
    • ゲストOS : Fedora 24 64bit
  • VirtualBox : Mac 上で動作する VirtualBox 5.1 で測定
    • CPU : 4コア
    • RAM : 4GB
    • チップセット: ICH9
    • ディスクコントローラ: SATA
      • ホストのI/Oキャッシュを使うオプション : オン / オフ それぞれで測定
    • 仮想ディスク : 32GB
      • ディスクタイプ : 可変VDI / 固定VDI それぞれで測定
      • 仮想ディスクの SSD フラグをON
    • ゲストOS : Fedora 24 64bit

テストケースは次のとおり。

テストケース テストモード テストサイズ ブロックサイズ 並列度
Single Sequential Read read 8GB 1MB QD1
Single Sequential Write write 8GB 1MB QD1
Multi Sequential Read read 8GB 128KB QD32
Multi Sequential Write write 8GB 128KB QD32
Single Random Read randread 4GB 4KB QD1
Single Random Write randwrite 4GB 4KB QD1
Multi Random Read randread 4GB 4KB QD32
Multi Random Write randwrite 4GB 4KB QD32
Multi Random R/W randrw 4GB 4KB QD32

実際には次のスクリプトを作成し実行しています。

#!/bin/bash

for i in {0..4}
do
    fio -direct=1 -invalidate=1 -name=SingleSeqRead -filename=fio.tmp -size=8G -bs=1M -iodepth=1 -rw=read >> 21-SingleSeqRead-O_DIRECT.log
    fio -direct=1 -invalidate=1 -name=SingleSeqWrite -filename=fio.tmp -size=8G -bs=1M -iodepth=1 -rw=write >> 22-SingleSeqWrite-O_DIRECT.log
    fio -direct=1 -invalidate=1 -name=MultiSeqRead -filename=fio.tmp -size=8G -bs=128K -iodepth=32 -rw=read >> 23-MultiSeqRead-O_DIRECT.log
    fio -direct=1 -invalidate=1 -name=MultiSeqWrite -filename=fio.tmp -size=8G -bs=128K -iodepth=32 -rw=write >> 24-MultiSeqWrite-O_DIRECT.log
    fio -direct=1 -invalidate=1 -name=SingleRandRead -filename=fio.tmp -size=4G -bs=4K -iodepth=1 -rw=randread >> 25-SingleRandRead-O_DIRECT.log
    fio -direct=1 -invalidate=1 -name=SingleRandWrite -filename=fio.tmp -size=4G -bs=4K -iodepth=1 -rw=randwrite >> 26-SigleRandWrite-O_DIRECT.log
    fio -direct=1 -invalidate=1 -name=MultiRandRead -filename=fio.tmp -size=4G -bs=4K -iodepth=32 -rw=randread >> 27-MultiRandRead-O_DIRECT.log
    fio -direct=1 -invalidate=1 -name=MultiRandWrite -filename=fio.tmp -size=4G -bs=4K -iodepth=32 -rw=randwrite >> 28-MultiRandWrite-O_DIRECT.log
    fio -direct=1 -invalidate=1 -name=MultiRandRW -filename=fio.tmp -size=4G -bs=4K -iodepth=32 -rw=randrw >> 29-MultiRandRW-O_DIRECT.log
done
rm fio.tmp

測定結果

f:id:miyahan:20161111000023p:plain

まずはシーケンシャルアクセス。リード性能はホストOSのキャッシュが効いているためか、VMware・VirtualBox(ホストキャッシュON) ともに物理マシンより高い値が出ています。特に固定ディスクの VirtualBox では異常なまでのハイスコアです。ちょっとリードテストの結果はまゆつばですな。

  • VirtualBox より VMware のほうが 16% (ブレ幅の大きかったSingle Sequential Read の結果を除くと8%) ほど高速
  • VirtualBox のホストキャッシュを切ると、リード性能が50％、ライト性能が12%低下する
  • VirtualBox の可変ディスクを固定ディスクにすると、リード性能が130%(まゆつば)、ライト性能が9%向上する

f:id:miyahan:20161111000024p:plain

つぎにランダムアクセス。ランダムR/Wの結果を見ると、どのVMも物理マシンの半分以下のパフォーマンスしか出せていないことがわかります。細かい読み書きを行うデータベースサーバーを仮想マシンで運用するのは厳しいということですね。

  • VirtualBox より VMware のほうが27%高速（特にリードが得意で、45%高速）
  • VirtualBox のホストキャッシュを切ると、リード性能が38％低下するが、ライト性能は15%向上した(!?)
  • VirtualBox の可変ディスクを固定ディスクにすると、リード性能が16%向上する（ライト性能は変わらず）

所感

VirtualBox vs VMware

総じて VMware は VirtualBox よりも速く、特にリードが得意でした。システムのパフォーマンスに影響するランダムR/Wの結果から、 VirtualBox は VMware より2割くらい遅いと言えるのではないでしょうか。VMware Fusion は有償ですし、VMware Workstation Player は商用利用(会社内での自学自習・お遊びを含む)できませんし、「タダなんだから仕方ない」で済む範囲内ですかね。

ホストキャッシュON vs OFF

場合によりけりだと思います。ただ前提として、ホストキャッシュを切るとパフォーマンスが半分以下になってしまう場合があると覚えておきましょう。ちなみに、今回はSSD環境でしたがランダムアクセスが弱いHDDだとライトバッファ(遅延書き込み)を利用することでライト性能も大きな効果があると思います。

ホストキャッシュをOFFにしたほうがよいケース

  • メモリサイズに余裕が無い場合
  • 不意にホストが死んでもデータロストが起きないことを保証しなくてはいけない場合
  • 仮想マシンを動かしながら、ホストOS側でもヘビーな作業を行う場合

ホストキャッシュをONにしたほうがよいケース

  • HDDのノートパソコンなど、ホストのディスクが遅い場合
  • 仮想マシンの動作中、ホストOS側であまり作業を行わない場合
  • データベースサーバーなど高いI/Oスループットが要求される場合

可変ディスク vs 固定ディスク

固定ディスク/キャッシュONでのシーケンシャルリードの結果がぶっちぎれているように、固定ディスクにするとホストキャッシュの効果を受けやすくなるようです。ただこれはベンチマークの性質上の話で、実際には固定ディスクにすると1割くらい高速になるかもしれない程度に考えておくのがよいでしょう。仮想ディスクのサイズ変更は面倒なので、余裕を持って多めに割り当てるのが一般的だと思いますが、それを固定ディスクで作ってしまうとディスクスペースを圧迫してしまい、バックアップも大変です。個人的にはこの程度の恩恵であれば可変ディスクでよいと思います。

おわりに

今回システム(macOS)が稼働しているSSD上にVMの仮想ディスクファイルを置いたため、テスト中にさまざまなバックグラウンド処理が走り結果が乱れてしまい苦労しました。

また最初は1GBでテストしたのですが、tempファイルがすべてメモリに乗ったためか数GB/s とかいうあり得ないスコアが出たので、多めにしてテストを全部やり直したりもしました。（それでも若干怪しい数字が出てしまいました･･･。）とくにかく時間もかかりますし、ベンチマークって大変だなあと思いました。（小並感）

Python の datetime.strptime がすんごく遅い件

プログラミング

会社でRADIUSサーバーの認証ログをリアルタイムに解析するツールを作っていたところ、思ったようなパフォーマンスが出ず、line_profiler というプロファイリングツールを使って調べたところ、処理時間の大部分を datetime.strptime で日時の文字列を datetime オブジェクトに変換する一行のコードが占めていました。

f:id:miyahan:20161112020142p:plainstrptime だけでスクリプト実行時間の83%を占めている。あきらかにここが原因

そこで、日時の文字列を自分で区切って datetime.datetime() に渡すようにしたところ、処理速度が飛躍的に向上しボトルネックは無くなりました。

下記サンプルコードを使ってベンチマークをしたところ、strptime はなんと4倍以上遅い！(実行環境: macOS Sierra / Python 3.5.2)

from datetime import datetime
import time

logtime_str = '20170101123456'
start = time.time()
for i in range(100000):
    dt = datetime.strptime(logtime_str, '%Y%m%d%H%M%S')
print('strptime: {:.4f}sec, dt:{}'.format(time.time() - start, dt))

# strptime: 2.2368sec, dt:2017-01-01 12:34:56

from datetime import datetime
import time

logtime_str = '20170101123456'
start = time.time()
for i in range(100000):
    dt = datetime(
        year=int(logtime_str[0:4]),
        month=int(logtime_str[4:6]),
        day=int(logtime_str[6:8]),
        hour=int(logtime_str[8:10]),
        minute=int(logtime_str[10:12]),
        second=int(logtime_str[12:14])
    )
print('self parse: {:.4f}sec, dt:{}'.format(time.time() - start, dt))

# self parse: 0.5266sec, dt:2017-01-01 12:34:56

Python 標準のプロファイリングライブラリ cProfile を視覚化する Python Call Graph というツールを使ってみました。

f:id:miyahan:20161105130657p:plain

正規表現は使い回しされているようですが、なぜか毎回ロケール情報を取りに行っていて結構な時間がかかっているようです。今回のコードでは使っていませんが、strptime は曜日( 'Monday', '月曜' )なども取り扱えるため、ロケールを解釈する処理が入っているのでしょうか。それにしても時間かかりすぎてません？使い方間違ってるのかな･･･。

テキストのパースは奥が深いことはわかりますが、よく使う標準ライブラリにこのような罠があるというのは少しショックです。。。

ほかの言語でも遅い？

(2016/11/8追記) 他の言語はどうなんだろうと思い、力不足ながらも比較してみました

vs Ruby

まずは、意識高い系言語 Ruby。こんなただ ruby の構文に置き換えただけのコード、Rubyist に見られたら八つ裂きにされそうですが、どうか勘弁してください。

miyahan$ ruby -v
ruby 2.3.1p112 (2016-04-26 revision 54768) [x86_64-darwin16]
require 'date'
require 'time'

logtime_str = '20170101123456'
start = Time.now
for i in 0..100000 do
    dt = DateTime.strptime(logtime_str, '%Y%m%d%H%M%S')
end
print('DateTime.parse: ', Time.now - start, 'sec. ')
print('dt: ', dt, "\n")

# DateTime.parse: 0.30088sec. dt: 2017-01-01T12:34:56+00:00

require 'date'
require 'time'

logtime_str = '20170101123456'
start = Time.now
for i in 0..100000 do
    dt = DateTime.new(
        logtime_str[0, 4].to_i,
        logtime_str[4, 2].to_i,
        logtime_str[6, 2].to_i,
        logtime_str[8, 2].to_i,
        logtime_str[10, 2].to_i,
        logtime_str[12, 2].to_i
    )
end
print('DateTime.new: ', Time.now - start, 'sec. ')
print('dt: ', dt, "\n")

# DateTime.new: 0.198785sec. dt: 2017-01-01T12:34:56+00:00

手動パースしたほうが34%ほど高速

vs PHP

次に、私の愛するゆるふわ言語 PHP。久しぶりに書くとドルやらセミコロンやらカッコやら面倒くさい。

miyahan$ php --version
PHP 7.0.12 (cli) (built: Oct 14 2016 09:56:59) ( NTS )
Copyright (c) 1997-2016 The PHP Group
Zend Engine v3.0.0, Copyright (c) 1998-2016 Zend Technologies
<?php
    $logtime_str = '20170101123456';
    $start = microtime(true);
    for ($i=0; $i<100000; $i++) {
        $dt = \DateTime::createFromFormat('YmdHis', $logtime_str);
    }
    print('DateTime:'.number_format(microtime(true) - $start, 5)."sec, ");
    print("dt:".$dt->format('Y-m-d H:i:s')."\n");

    # DateTime:0.21719sec, dt:2017-01-01 12:34:56

<?php
    $logtime_str = '20170101123456';
    $start = microtime(true);
    for ($i=0; $i<100000; $i++) {
        $ts = mktime(
            substr($logtime_str, 8, 2),
            substr($logtime_str, 10, 2),
            substr($logtime_str, 12, 2),
            substr($logtime_str, 4, 2),
            substr($logtime_str, 6, 2),
            substr($logtime_str, 0, 4)
        );
    }
    print('mktime:'.number_format(microtime(true) - $start, 5)."sec, ");
    print("dt:".date('Y-m-d H:i:s', $ts)."\n");

    # mktime:0.18713sec, dt:2017-01-01 12:34:56

<?php
    $logtime_str = '20170101123456';
    $start = microtime(true);
    for ($i=0; $i<100000; $i++) {
        $ts = gmmktime(
            substr($logtime_str, 8, 2),
            substr($logtime_str, 10, 2),
            substr($logtime_str, 12, 2),
            substr($logtime_str, 4, 2),
            substr($logtime_str, 6, 2),
            substr($logtime_str, 0, 4)
        );
    }
    print('gmmktime:'.number_format(microtime(true) - $start, 5)."sec, ");
    print("dt:".date('Y-m-d H:i:s', $ts)."\n");

    # gmmktime:0.14538sec, dt:2017-01-01 12:34:56

手動パースは、モダンな DateTime クラス を使うより33％高速。ただし、GMTと見なして処理する gmmktime() の代わりに、自環境のタイムゾーンを考慮する mktime() を使うと、その差は14%ほどに縮まるので、DateTime クラスを使うことのオーバーヘッドはそこまでないと思います。

まとめ

言語 高級な方法 高速な方法 比
Python 3.5 2.2368s 0.5266s 428%
Ruby 2.3 0.3009s 0.1988s 151%
PHP 7.0 0.2172s 0.1454s 149%

Ruby も PHP も高級な機能を使うことによりで処理時間が50%ほど増えています。ただ一般的なアプリケーションであれば、その柔軟で強力な機能を簡潔なコードで実現できるというメリットに対して、十分ペイできるオーバーヘッドだと思います。一方 Python は428%とちょっと許容できない、というかバグじゃないかと疑うレベルです･･･。

それにしても、Python っておっそいですね･･･。というか PHP 大健闘。

Mac mini のメモリをRMAするの巻

コンピューター

これまでの流れ

miyalog.hatenablog.jp

('A`) ...

無限アップデート地獄

f:id:miyahan:20161025174912j:plainf:id:miyahan:20161025174916j:plain

先日、自宅サーバーとして使っている Mac mini (Mid 2011) を macOS Sierra にアップグレードしようとしたところ、インストール → 失敗 → 再起動 → インストール → 失敗... の無限ループに陥り起動しなくなってしまいました。

f:id:miyahan:20161025174934j:plain

指示通り AHT (Apple Hardware Test) をしてみると、テストの途中でフリーズしてしまいました。何らかのハードウェア障害が発生しているようです。ためしにメモリを昔使っていたものに取り替えてみたところ、AHTが完走し、Sierraのアップデートも無事完了しました。

f:id:miyahan:20161025175611p:plain

たしかに以前からたまにカーネルパニックが起きたり、kaspersky でたびたび「ウイルス定義ファイルが破損しています」という警告がでたりと不安定ではありました。なるほどメモリか。メモリに乗ってるウイルス定義ファイルのデータが化けて、チェックサムか何かで検出された的な？

Let's RMA

現在使用しているメモリはCFD販売の永久保証がついたものだったので、お言葉に甘えて交換してもらうことに。

CFD販売は基本的に販売店対応になるらしいのですが、自分の場合は Amazon (通販) で買ったので、CFD販売 サポート案内 にあるテンプレを記入して直接メーカーにメール。2日後に返信があり、次のものをそろえて返品受付センタに送ってくれとのこと。

  • 商品（メモリ本体）
  • 保証書（メモリの場合は商品のパッケージが保証書になるらしい）
  • メールに添付されてきた「修理依頼書」(Microsoft Excel 必須）
  • 購入時のレシート・納品書のコピー

荷物を送った数日後、よくある「終売品につき、同等品への変更でもいい？」みたいな連絡がきつつ、計一週間で代替品が届きました。日本語だと楽ですねー。

f:id:miyahan:20161025180700j:plainf:id:miyahan:20161025180706j:plain

さっそく Mac mini に取り付け。

f:id:miyahan:20161025180758j:plain

それにしても、立て続けに Mac が3台故障･･･。Mac Pro の修理に5万、iMac の買い替えに25万。そして iPad Pro で 9万、iPhone 7 plus で 10.5万･･･。今年はどんだけアップルに貢いでるんだｗ