こんにちは。 Cariot事業部の遠藤です。
ブログでは2回目の登場になります。ちなみに前回の記事はこちら(↓)
Jenkins × AWS CodeBuild × GitHubで複数コンテナを利用したビルドを試してみた - フレクトのクラウドblog re:newal
さて!
絶賛賑わいを見せている、ラスベガスで開催中のre:Invent 2018ですが、フレクトからは今年は4名、参加しています。
初日が終わったので、感想を書いていきますね(現地時間23:00)。
続きを読むこんにちは。 Cariot事業部の遠藤です。
ブログでは2回目の登場になります。ちなみに前回の記事はこちら(↓)
Jenkins × AWS CodeBuild × GitHubで複数コンテナを利用したビルドを試してみた - フレクトのクラウドblog re:newal
さて!
絶賛賑わいを見せている、ラスベガスで開催中のre:Invent 2018ですが、フレクトからは今年は4名、参加しています。
初日が終わったので、感想を書いていきますね(現地時間23:00)。
続きを読むエンジニアの佐藤です。こんにちは。今回は自分の作業上のメモみたいな話です。
筆者は日常の開発作業をクラウドインスタンスで行うことがあります。開発環境はDockerコンテナで実装した仮想デスクトップサーバーです。
この開発環境、少し前にUbuntu 18.04のコンテナイメージから作り直したのですが、、、なんとmanページが一切使えません。
$ man git No manual entry for git
調べていくと、なんとmanページのインストールが、以下の設定によって全部スキップされていました。
$ cat /etc/dpkg/dpkg.cfg.d/excludes # Drop all man pages path-exclude=/usr/share/man/*
このpath-exclude指定している行をコメントアウトし、git, git-manを再インストールすると、問題は解決しました。
Ubuntu 18のコンテナは初期イメージサイズを大幅に削減したと言われていましたが、こういう過激な方法が取られていたとは知りませんでした。まぁ、Dockerは通常サーバーとして使われ、筆者のようにクライアントとして使っている人はあまりいないということなのでしょう。
エンジニアの佐藤です。こんにちは。今回はネットワークインフラのお話を書かせていただきたいと思います。
猛暑が続くある日のこと、お客さまから、とある開発システムの、とある機能が「動かないんだけど」という連絡を受けました。
筆者はすぐに問題現象を確認しましたが、確実に再現し、弁解の余地はありません。お詫びして、原因調査に取りかかりました。
この機能の実装はこうです。Salesforce(Visualforceページ)からApex処理を経て外部システムAにRESTリクエストを送信する。外部システムAはさらに外部システムSにRESTリクエストを送信する。レスポンスは順次回収され、適宜加工され、結果がSalesforce画面に表示される、というものです。 図に描くとこんな感じです。
報告された問題現象とは、ブラウザが10秒ほど応答停止したのちに、エラーが画面に表示されるというものです。エラーの内容から、筆者は、Salesforceがまともなレスポンスを受け取っていないんだろうと推測しました。そして10秒ブロックですから、一連のリクエスト連鎖のどこかでタイムアウトしたんだろうと思いました。筆者は外部システムAのログを観察しました。すると。。。外部システムSをリクエストする直前のログを最後に足取りが途絶えていました。
きっとSalesforceからシステムAへのリクエストが10秒でタイムアウトし、Visualforceページのエラーへとつながっていったのでしょう。
図に描くとこんな感じです。
次に筆者が疑ったのは、システムSです。実はシステムSは今回の機能開発に合わせて平行開発されたもので、開発中は多少問題があったこともあったのです。筆者はシステムAの内部から、Pythonの即席コードでシステムSにリクエストしてみました。すると。。。何の問題もなくレスポンスがあります。
「他人を最初に疑うのは良くないよな」と反省した筆者は、問題現象発生時のパケットキャプチャを採取することにしました。すると。。。システムSへのリクエストはそもそも送信されていないことがわかりました。そんなバカなと思って2度3度やってみましたが、結果は変わりません。技術者たる者、事実の前には謙虚でなくてはなりません。 リクエストがタイムアウトしたのではなく、そもそもリクエストしていなかったのです。
ここで筆者は困ってしまいました。というのも、このシステムA、他にも似たような処理を常時続けており、そちらには何の問題もないからです。DockerコンテナのJava実装された単一のプロセスで、あっちはよくてこっちはダメという状態なのです。システムAからリクエスト可能であることは、図3で確認されていますから、原因はシステムA側にあるはずです。
筆者はこの段階で、Dockerコンテナの再起動を考えました。どう考えてもおかしいので、コンテナプロセス内部に何か一時的な問題が起こっているのだろうと考えたのです。幸いロードバランサ化のコンテナクラスタで、ドレーンしてから再起動することで無停止再起動が可能でしたので、許可を得て実行しました。すると。。。ログにソケット強制クローズの警告が数十個出力されました。スローされた例外は org.apache.http.impl.execchain.RequestAbortedException 、「リクエストしたが、返事が来る前に、棄てられた。」
そんなばかな。システムSへのリクエストは、システムAにログインしてPython即席コードを実行すれば、通るのですよ。受信待機になるはずがないのです。DockerコンテナでBridgeネットワークを経由している点がPython即席コードと違うといえば違いますが、リクエスト先がシステムS以外の場合は成功しており、Dockerが原因とは考えにくい。
その一方で、コンテナ再起動により当初の機能は回復しました。レスポンス待ちのソケットを強制クローズすれば、システムAからシステムSの、新しいリクエストは通るのです。謎は以下2つに絞り込まれました。
そのうち調査するか。。。と思っていた筆者でしたが、翌日再びお客さまから「やっぱり、動かないんだけど」の連絡が。。。
そんなばかな。。。こうなるともう逃げ道はない。筆者は覚悟を決めて徹底追及することにしました。
筆者は再び機能不全に陥ったシステムAを調査し、Dockerコンテナプロセスに多数の受信待ちソケットがあることを確認しました。
なぜこのようなソケットが発生するのか?筆者が次に疑ったのは、NATでした。実はこのシステムA、AWS VPCのプライベートネットワークセグメントに立てられたECSクラスタ上のサービスとして実装されており、アウトバウンドリクエストはVPCのNATゲートウェイを経由することにしていたのです。NATゲートウェイの詳細な仕様は以下の公式ページに書かれています。
Comparison of NAT Instances and NAT Gateways
https://docs.aws.amazon.com/AmazonVPC/latest/UserGuide/vpc-nat-comparison.html
詳しく読んでいくと、タイムアウトに関する以下のような記述がありました。
Timeout behavior
NAT Gateway: When a connection times out, a NAT gateway returns an RST packet to any resources behind the NAT gateway that attempt to continue the connection (it does not send a FIN packet).
NAT Instance: When a connection times out, a NAT instance sends a FIN packet to resources behind the NAT instance to close the connection.
NATについては、以前AWSはNAT用に特別調整したAMI(NAT Instance AMI)を提供して適宜使ってくれという姿勢でしたが、ある時からこれがサービス化され、NATゲートウェイと名付けられました。そして、その際になぜか、仕様が変わったようです。今回使っているのはNATゲートウェイですから、仮にもしシステムSへのリクエストがタイムアウトすると、システムA側には、何も通知されない。システムAから何か催促すればRSTパケットを返すとありますが、 HTTPリクエストが終わっていて、TCPキープアライブも設定されていなければ(今回は設定されていない)、そのような催促はない。永久待機です。
疑い深い筆者は、Python即席コードで悪いHTTPサーバーを書いて、受信待機ソケットの再現を試みました。
PORT = 8000 def Handler(request, client_address, server): n = int(sys.argv[1]) print('wait {} secs'.format(str(n))) time.sleep(n) print('no response return') with socketserver.TCPServer(("", PORT), Handler) as httpd: print("serving at port", PORT) httpd.serve_forever()
このサーバー、リクエストされたら指定秒数間スリープしたのち、何も言わずにソケットをクローズするという迷惑なものです。
クライアントは同じくPythonで以下のように実装しました。これ以上ない簡単な実装です。
address = sys.argv[1] print('requesting ' + address) res = requests.get(address) print(res)
手元で実験すると、以下のようになりました。
$ python3 innocent_client.py http://localhost:8000 requesting http://localhost:8000 (中略) requests.exceptions.ConnectionError: ('Connection aborted.', RemoteDisconnected('Remote end closed connection without response',))
なお、requests、特別に指定しないとタイムアウトはなし、つまり返信があるまで無制限待機となります。
http://docs.python-requests.org/en/master/user/advanced/#timeouts
これをNATゲートウェイ越しで動作させると。。。できました!サーバー側で360秒後にソケットをクローズしたにも関わらず、クライアント側では受信待機のソケットが、「来ぬ人を」待ち続けています。
ここまで来ると受信待機ソケットの滞留を防止する方法は、タイムアウト設定ということになります。筆者は以下のようにタイムアウトを設定しました。
CloseableHttpClient httpClient = HttpClients.custom() (中略) .build(); HttpComponentsClientHttpRequestFactory requestFactory = new HttpComponentsClientHttpRequestFactory(); requestFactory.setHttpClient(httpClient); requestFactory.setConnectTimeout(connectionTimeout); // タイムアウト追加 requestFactory.setReadTimeout(readTimeout); // タイムアウト追加 RestTemplate restTemplate = new RestTemplate((ClientHttpRequestFactory)requestFactory);
しかしこのタイムアウト、デフォルトでは無制限なのでしょうか?
調査すると、なんと「デフォルトでは無制限」のようでした。。。
https://hc.apache.org/httpcomponents-client-4.2.x/tutorial/html/connmgmt.html
CoreConnectionPNames.SO_TIMEOUT='http.socket.timeout': (中略) If this parameter is not set, connect operations will not time out (infinite timeout).
このコードをコミットすると、見事に問題現象が起こらなくなりました。どうやら問題現象の原因要因に正しくアプローチできたようです。
問題現象が解決してしまったのでこの点は謎なままなのですが、筆者は「リクエストスレッドプールが違っていたから」だと考えています。図4に戻りますが、システムDはAWS SDKを使用して呼び出しており、システムSはApache HTTP Componentsで呼び出していました。2つのリクエストスレッドプールが独立して確保されていたので、システムS側のプールスレッドが全部受信待機になったとしても、システムD側のプールスレッドには影響しなかったのでしょう。
最後の謎として、「システムSが通常応答するなら、なぜタイムアウトになったのか」という点があります。これについては、いまだに特定されていません。ひょっとすると普段は順調なのに夜間はダメとかなのかもしれません。
今回の問題を反省に、リクエストには必ずタイムアウトを設定する習慣をつけたいものです。今回調べたPythonのRequestsライブラリもJavaのApache HTTP Componentsも、既定のタイムアウトは「なし」なのです。なんらかの理由でパケットが棄てられたら、「来ぬ人を」永久待機ということに容易になってしまいます。
最後までお読みくださり、ありがとうございました。
みなさんこんにちは。エンジニアの佐藤です。今回はAndroid開発について書かせていただきたいと思います。と言っても、Androidアプリではなく、開発環境であるAndroid Studioについてです。
筆者は業務をしばしばVDI(仮想デスクトップ)環境で行なっています。
理由はネットワークの速度とリソースの柔軟性です。
VDIをホストするクラウドインスタンスは、ネットワークが速く、安定しています。オフィスの回線とは比較になりません。多量のデータを出し入れする仕事では、効率が上がります。また、CPU、メモリ、ストレージもその時の仕事に合わせて確保し、終わったら解放できますので、経済的です。
しかし、スマホ開発は別でした。これらの開発ではエミュレータを実行する必要があり、エミュレータは通常、ハードウェア仮想化機能を利用します。(仮想化オフでも動きますが、とてつもなく遅い。) 一方、クラウドインスタンスはそれ自体ハードウェア仮想化の中で動作しているため、ここでさらにハードウェア仮想化を利用するアプリを動かすことは、できなかったのです。
いえ、あるにはあったのですが、以下のような特別な仕掛けが必要でした。
Nested virtualization: How to run nested KVM on AWS or Google Cloud
https://blogs.oracle.com/ravello/run-nested-kvm-on-aws-google
仕方がないので筆者は苦肉の策で、クラウドインスタンスのAndroid Studioと、ローカル環境のエミュレータをつないだりしていました。
Android仮想デバイスとDocker開発環境をつなぐ http://blog.flect.co.jp/cloud/2017/04/androiddocker-c3b5.html
しかし昨年、ついにクラウドインスタンスでもハードウェア仮想化が利用可能になりました。ありがたいことに、追加コストはかかりません。
AWSについては情報がありませんが、AzureとGCPでサポートが表明されました。
Introducing nested virtualization for Google Compute Engine.
Thursday, September 28, 2017
https://cloudplatform.googleblog.com/2017/09/introducing-nested-virtualization-for.html
Nested Virtualization in Azure.
Posted on July 13, 2017
https://azure.microsoft.com/en-us/blog/nested-virtualization-in-azure/
今回はこの機能を使って、GCPインスタンスで実行される仮想デスクトップ上でAndroid仮想デバイス(AVD)を「ハードウェア仮想化を使って」実行してみたいと思います。結論から言うと、この試みは目論見通りに成功しました。
GCPインスタンスでハードウェア仮想化を有効にする手順は、以下の公式ドキュメントに書かれています。
Enabling Nested Virtualization for VM Instances https://cloud.google.com/compute/docs/instances/enable-nested-virtualization-vm-instances
手順はまず、ハードウェア仮想化を有効にした起動イメージを作成することから始まり、コマンドラインで実行する必要があります。この有効化、ライセンス付与という形態を取っていますが課金はありません。
gcloud compute images create nested-vm-imad --source-disk masashi-tw02 --source-disk-zone asia-east1-b \ --licenses "https://www.googleapis.com/compute/v1/projects/vm-options/global/licenses/enable-vmx"
次にこの起動イメージでインスタンスをスタートします。このときプロセッサアーキテクチャにHaswellまたはSkylakeを指定します。
gcloud compute instances create example-nested-vm --zone asia-east1-b \ --image nested-vm-image
このインスタンスにSSHでログインして以下のコマンドを打って、「1」が返ることを確認します。
grep -cw vmx /proc/cpuinfo 1
これでハードウェア仮想化が有効になったはずです。Android Studioを実行してみましょう。
筆者は前出の「Docker開発環境」を使いました。ハードウェア仮想化とはつまりCPUの特別命令セットの使用のことですので、コンテナを特権モード(privileged=true)で動作させれば動作するのではないかと目論んでのことです。Android Studioを直接インストールするのではなく、インストール済みのコンテナをスタートさせました。
Android Studioを起動したらAVD一覧を開き、AVDを追加します。この時 Select system image の所で「x86 images」の中から選択します。
こうして作成したAVDを起動すると。。。ありゃ、エラーです。
/dev/kvm のアクセス権が無いと言われてしまったので、このデバイスのオーナーをAVDの実行ユーザーに変えました。
sudo chown user1.user1 /dev/kvm
再度AVDを起動すると。。。動きました!この速度、確かにハードウェア仮想化の速さです。
試しにHello Worldを動かしてみると、ローカル環境同様に開発アプリがAVDにロードされました。
ようやく念願の「クラウド仮想デスクトップ+AVD」が実現したのですが、その性能はいかほどのものでしょうか。正直に言いますと、 「耐えられないほどではないが、かなり遅い」というのが筆者の正直な印象です。
ハードウェア仮想化を有効にしてもなお遅い理由として、仮想デスクトップなのでグラフィックのハードウェア支援が一切無いことが原因として考えられます。特にスマホアプリはアニメーションを多用し、通常は中間フレームはハードウェア支援で描画しますので、これを全部CPUでこなして、かつ、ネットワークで転送しなければならないというハンディが動作を遅くしていることは容易に想像できます。
ですが、全てのアプリケーションが常時激しいアニメーションを行うわけではないと思いますので、これは使い方次第なのではないでしょうか。
もう一つの問題として、AVDが多量のリソースを消費することがあります。図はAVDの実行中にtopコマンドでメモリ消費を調べたものですが、3GBを超えるメモリが使われています。
今時のスマホの性能を考えると仕方がないのかもしれませんが、しかし、この点についてはクラウドですし、メモリもCPUも時間買いできますので、必要なだけ確保すれば良いと思います。
ローカル環境と比べてメリットもあります。Android StudioもAVDも、初回インストール時のダウンロード容量がとにかく多く、オフィスや家庭の回線では非常に辛いものがあります。この点クラウドインスタンスのネットワークは高速でかつ安定しているので、なんでもサクサクダウンロードできてしまいます。 スタートアップまでの時間は、まちがいなくクラウドの方が速いでしょう。インストール済みコンテナやイメージを素早く展開できるという利点もあります。
今回の知見は、機会があればぜひ活用したいと思います。最後までお読みいただきありがとうございました。
みなさんこんにちは。エンジニアの佐藤です。今回はIoTの話題をご紹介させていただきたいと思います。
先日、とあるIoTシステムのログデータをETL(Extract, transform, load)処理によりDWHに収めました。このシステムは運用暦約1年で、利用量は右肩上がりで上昇してきました。蓄積データの活用が企画され、数億件のデータがDWHに集積されました。多数のデバイスが毎日送信して積み上げてきたものです。
ですが、およそコンピュータと名の付く物、何事も疑いの目で見なければなりません。筆者がまず気になったのは、「まともなデータなのか」という点です。数億レコードともなると、もはや個別確認はできません。どんなゴミが混入しているのかわかったものではありません。
「まともなデータ」の基準はいろいろあると思いますが、筆者が一番重要だと思うのは、一意性です。RDBMSで言えば「テーブルのキー項目は何か」ということになります。DWHにユニーク制約はありませんから、スキーマが一意性を担保することはありません。まずこの点から確認する必要があります。
このシステムの場合、送信データにはデバイスのID、対象事象発生時のデバイス時刻、シーケンス番号が含まれています。シーケンス番号は電源OFFでリセットされますから、一意ではありませんが、デバイスのIDは重複がないことが保証されています。時刻は外部の信頼できる時計に自動補正ですから、一旦正確だと前提しましょう。詳細は省きますが、 デバイスID、事象発生時のデバイス時刻、ログ到着時刻の全てが重複することは、仕様上無いはずです。 DWHにはBigQueryを使っていますので、以下のようにクエリしてこの点を確認してみました。
#standardSQL SELECT xxxxx AS dt_log, xxxxx AS device_id, xxxxx AS device_time, COUNT(*) count FROM table02 WHERE _PARTITIONTIME = TIMESTAMP('2018-06-10') GROUP BY dt_log, device_id, device_time HAVING count > 1 ※ 一部は伏字または仮の値にしています。 +-------------------------+-----------+---------------------+-------+ | dt_log | device_id | device_time | count | +-------------------------+-----------+---------------------+-------+ | 2018-06-10 00:00:00.045 | 4641 | 2018-06-09 23:59:56 | 2 | | 2018-06-10 00:00:00.572 | 9458 | 2018-06-09 23:59:57 | 2 | | 2018-06-10 00:00:00.014 | 9499 | 2018-06-09 23:59:57 | 2 | | 2018-06-10 00:00:00.235 | 1686 | 2018-06-09 23:59:58 | 2 | | 2018-06-10 00:00:00.195 | 1712 | 2018-06-09 23:59:58 | 2 | +-------------------------+-----------+---------------------+-------+
それ見たことか。ダブりデータです。 日付が変わった直後から約1秒間の間で発生しているように見えます。念には念を入れて受信した生データも比較してみましたが、完全に重複しています。 これはいわばデータの「バグ」。原因を特定せねばなりません。
同じデータが2回DWHに登録された理由は何か?この原因追求のために役立つのが、私が「経路情報」と呼んでいる、レコードの出自に関する記録です。ETL処理の節目ごとにこの経路情報を追記していき、全てのレコードについて元ネタが特定できるように仕掛けておくのです。
今回のダブりデータについて経路情報(log_file_pos)を表示すると、以下のようになりました。簡単に解説しますと、「2018-06-09/1/343159(00717206)/00」は、2018年06月09日のログファイルに記録された、受信ホスト1番が出力したログファイルの第343159番目のデータで、ファイルの第717206行目に記録されている、という意味です。(末尾の「/00」は説明を省略します。)
+-------------------------+-----------+---------------------+----------------------------------+ | dt_log | device_id | device_time | log_file_pos | +-------------------------+-----------+---------------------+----------------------------------+ | 2018-06-10 00:00:00.235 | 1686 | 2018-06-09 23:59:58 | 2018-06-09/1/343159(00717206)/00 | | 2018-06-10 00:00:00.235 | 1686 | 2018-06-09 23:59:58 | 2018-06-10/1/003(00000006)/00 | | 2018-06-10 00:00:00.195 | 1712 | 2018-06-09 23:59:58 | 2018-06-09/1/343158(00717205)/00 | | 2018-06-10 00:00:00.195 | 1712 | 2018-06-09 23:59:58 | 2018-06-10/1/002(00000005)/00 | | 2018-06-10 00:00:00.045 | 4641 | 2018-06-09 23:59:56 | 2018-06-09/1/343157(00717202)/00 | | 2018-06-10 00:00:00.045 | 4641 | 2018-06-09 23:59:56 | 2018-06-10/1/001(00000002)/00 | | 2018-06-10 00:00:00.572 | 9458 | 2018-06-09 23:59:57 | 2018-06-09/1/343160(00717207)/00 | | 2018-06-10 00:00:00.572 | 9458 | 2018-06-09 23:59:57 | 2018-06-10/1/004(00000007)/00 | | 2018-06-10 00:00:00.014 | 9499 | 2018-06-09 23:59:57 | 2018-06-09/1/343156(00717201)/00 | | 2018-06-10 00:00:00.014 | 9499 | 2018-06-09 23:59:57 | 2018-06-10/1/000(00000001)/00 | +-------------------------+-----------+---------------------+----------------------------------+
この経路情報をダブりデータで比較してみると、連続する2つの日付の、ちょうど境界あたりに分布していることがわかります。ここまでくると、ダブりの原因は、日付ごとにログファイルを分ける処理にある可能性が高いと考えるのが妥当でしょう。
今回ETL処理のインプットとなったログファイルは、AWS CloudWatch Logsに出力されたログを定期的にエクスポートしてS3へ保存させたものです。このエクスポート処理の設定は定時ジョブで実行しており、以下のようになっています。
client = boto3.client('logs') response = client.create_export_task( logGroupName = log_group_name, fromTime = from_ts * 1000, to = to_ts * 1000, destination = s3_bucket_name, destinationPrefix = s3_prefix )
from_ts と to_ts はちょうど24時間(=86400秒)離れています。一見良さそうですが、この種の境界設定については、常に「inclusive(指定値を含む)」なのか「exclusive(指定値は含まない)」かを注意する必要があります。以下のURLからAPIの仕様を確認してみましょう。
https://docs.aws.amazon.com/AmazonCloudWatchLogs/latest/APIReference/API_CreateExportTask.html
Request Parameters
- from
- The start time of the range for the request, expressed as the number of milliseconds after Jan 1, 1970 00:00:00 UTC. Events with a time stamp earlier than this time are not exported.
- to
- The end time of the range for the request, expressed as the number of milliseconds after Jan 1, 1970 00:00:00 UTC. Events with a time stamp later than this time are not exported.
否定形で書かれていますが、本質的には inclusiveです。 つまり、ちょうど24時間分(=86400000ミリ秒)離れた2つの値をtoとfromに指定した場合、1ミリ秒分はダブる ということです。この点については、不注意だったと言えます。
原因がわかりました!と言いたいところですが、あれ?何かおかしいですよね。ダブりデータは「2018-06-10 00:00:00.045」から「2018-06-10 00:00:00.572」に分布していたのです。1ミリ秒ではなく、1秒ですね。結局AWSのこのAPI、ミリ秒指定と言っておきながら、ミリ秒部分は評価していないようです。
上記のAPIリファレンスの文章に当てはめてみましょう。2018-06-09のログファイルについて、
from: Events with a time stamp earlier than 2018-06-09 00:00:00.000 are not included.
to: Events with a time stamp later than 2018-06-10 00:00:00.000 are not included.
となっているわけですが、実際には 2018-06-10 00:00:00.000 から、少なくとも2018-06-10 00:00:00.572 までのログが、入ってしまっているわけです。 ミリ秒単位で指定させておきながら、これはひどいよな、と思います。
AWSのAPI仕様はわかりました。では、以下のようにエクスポート設定コードを改めればOKでしょうか?
client = boto3.client('logs') response = client.create_export_task( logGroupName = log_group_name, fromTime = from_ts * 1000, to = (to_ts * 1000) - 1, destination = s3_bucket_name, destinationPrefix = s3_prefix )
つまり、2018-06-09のログファイルについては以下のような指定になるわけです。
from: Events with a time stamp earlier than 2018-06-09 00:00:00.000 are not included.
to: Events with a time stamp later than 2018-06-09 23:59:59.999 are not included.
筆者は、これは危険な設定だと思います。今度はエクスポートの欠損が起こる可能性があるからです。 例えば、CloudWatch Logsにログが 2018-06-09 23:59:59.9995 に到着したら、取りこぼされてしまいます。
では、本当に23:59:59.9995などというタイミングでログが到着したという事象が発生するのでしょうか?
以下のCloudWatch Logsログ取得APIの仕様によると、
https://docs.aws.amazon.com/AmazonCloudWatchLogs/latest/APIReference/API_GetLogEvents.html
https://docs.aws.amazon.com/AmazonCloudWatchLogs/latest/APIReference/API_OutputLogEvent.html
ログの収録時刻(ingestionTime)は「ミリ秒単位の整数」となっていますので、23:59:59.9995は、23:59:59.999か、翌日00:00:00.000に丸められるでしょうから、現時点では大丈夫そうではあります。
しかし現在巷で使用されているハードウェアクロックの時間分解能は1ナノ秒となっており、AWS CloudWatch Logsがミリ秒よりさらに細かい到着時刻記録をサポートした場合、取りこぼしの心配が生じる可能性があります。(あくまで仕様上の話ですが。。。)
筆者の結論としては、このエクスポート設定コードは、このままにしておくことにしました。 データの受信記録が永久的に失われるというのは非常に恐ろしい出来事ですので、潜在的な危険はできるだけ排除したい。それなら多少の手間をかけ、後から重複を除去した方がマシ、だと思ったのです。
これでダブりデータの原因は特定されました。安心して眠れそうです。。。しかし、本当にそうなのでしょうか…?
疑い深い筆者は、今度は「00:00:00.000 ~ 00:00:00.999 以外の時間帯のダブりデータ」を探してみました。そして。。。見つけてしまったのです。
+-------------------------+-----------+---------------------+---------------------------------+ | dt_log | device_id | device_time | log_file_pos | +-------------------------+-----------+---------------------+---------------------------------+ | 2018-06-12 14:37:31.449 | 4896 | 2018-06-12 14:36:54 | 2018-06-12/2/65245(00158574)/00 | | 2018-06-12 14:37:31.449 | 4896 | 2018-06-12 14:37:00 | 2018-06-12/2/65258(00158587)/00 | | 2018-06-12 14:37:31.449 | 4896 | 2018-06-12 14:37:00 | 2018-06-12/2/65244(00158573)/00 | | 2018-06-12 14:37:31.449 | 4896 | 2018-06-12 14:37:03 | 2018-06-12/2/65246(00158575)/00 | | 2018-06-12 14:37:31.449 | 4896 | 2018-06-12 14:37:03 | 2018-06-12/2/65250(00158579)/00 | | 2018-06-12 14:37:31.449 | 4896 | 2018-06-12 14:36:54 | 2018-06-12/2/65248(00158577)/00 | | 2018-06-12 14:37:31.449 | 4896 | 2018-06-12 14:36:57 | 2018-06-12/2/65257(00158586)/00 | | 2018-06-12 14:37:31.449 | 4896 | 2018-06-12 14:36:57 | 2018-06-12/2/65247(00158576)/00 | | 2018-06-13 00:44:05.565 | 2164 | 2018-06-13 00:43:57 | 2018-06-13/2/61588(00078056)/00 | | 2018-06-13 00:44:05.565 | 2164 | 2018-06-13 00:43:57 | 2018-06-13/2/61587(00078055)/00 | +-------------------------+-----------+---------------------+---------------------------------+
このダブりはこれまで特定した原因だけでは説明できません。一体何が起こったのか、筆者は元ログを調査しました。その結果、同時刻に同一データの到着が2回記録されていることを発見してしまいました。
158575 2018-06-12 23:37:31.449 : trackingProc len:36 data:4dxxxx... 158579 2018-06-12 23:37:31.449 : trackingProc len:36 data:4dxxxx... ※ ここでは時刻はデバイスからのデータを受信するインスタンスのシステム時刻で、JSTで書かれている。
そんなばかなと思ってログファイルのエクスポート元のAWS CloudWatch Logsもクエリしてみましたが、上記の2行のログは、全く同時刻に到着しています。
$ aws logs get-log-events --cli-input-json "`cat query_aws_logs.json`" --profile=xxxx | jq -r '.events[]|select(.message | contains("4dxxxx..."))|.ingestionTime' 1528814254774 1528814254774
次はネットワーク通信ログを、と言いたいところですが、残念ながらここまでは記録していませんでした。どこかで想定外の重複動作があったのでしょうが、真実はやぶの中です。原因が特定できないので対策方針が立つわけもなく、データクレンジングで対処するしかありません。今回の場合は同一デバイス・同一時刻に発生する物理事象はひとつに決まっていますから、ダブりデータのうちひとつだけを採用すれば良いでしょう。
ここまでくると、「もう何を信じて良いやら」という気持ちになってきました。結局ログの記録、転送のそれぞれの段階で、ぴったり完璧とは行かない例外事象が起こってしまっているのです。そしてマニュアルも厳密でなく、オーナーシップがあるわけでもないので仕様は変わる。こういう状態でデータ分析をやるときは、いかなるポリシーを定めて事に取りかかればいいのでしょうか?
筆者の結論は以下のようなものです。
プログラムコードのデバッグにも似た対策措置が、データに対しても必要なようです。
最後までお読みいただき、ありがとうございました。
みなさんこんにちは。エンジニアの佐藤です。今回はCloud Vision APIの活用について書かせていただきたいと思います。
先日の Google I/O 2018 で、チャットボットが電話をかけて音声で美容室を予約するデモがあり、先進的事例として話題になりました。こうなると「この種の単純作業はAIに置き換わり、失業が社会問題になるのではないか。」という不安が募ります。しかし筆者の知っている範囲では、コンピュータの認識能力の柔軟性は、未だ人間には遠く及ばないと思います。 ただし、現時点で既に人間が追い越されている特性もあると思います。それは スピードと評価の安定性です 。24時間休みなく多数の画像判断を完全に一定の基準で実行することは、人間にはできません。しかしコンピュータは十八番です。 今回はこの特性を評価して、 Webサイトの画像全部の総合評価とWebサイト間の比較 を試みたいと思います。
筆者が選んだのは、大手リテールサイトのR社とA社です。どちらもホームページには100枚以上の商品などの画像があり、商品ジャンルも多岐にわたっています。 比較しようにも、評価観点が定まりそうにありません。そこで、これらの画像を全部、Cloud Vision APIでラベル検出させてみます。
最初に両サイトの画像を個別ファイルとして保存し、次にそれぞれのファイルをCloud Vision APIでラベル検出させます。 結果はすべてPostgresqlに保存し、SQL言語でクエリして評価します。
ラベル検出の仕様は以下のサイトに書かれていますが、
https://cloud.google.com/vision/docs/labels そのレスポンスは以下のように、「何が」「どのくらい確からしく」写っていたのかを答えてくれるというものです。
"labelAnnotations": [ { "topicality": 0.9604079, "score": 0.9604079, "mid": "/m/01bqk0", "description": "bicycle wheel" }, { "topicality": 0.9501146, "score": 0.9501146, "mid": "/m/019sc", "description": "black" }, ... { "topicality": 0.58060855, "score": 0.58060855, "mid": "/m/0h8n8m2", "description": "ventilation fan" }, ...
この通りレスポンスには複数のラベルが返され、色や形状など、様々な観点が含まれています。この場合は黒色の卓上クリップ扇風機なのですが、認識結果として最も正しいのは最もscoreの低い「ventilation fan」です。(やはり単発では、コンピュータは人間にはかなわないのです。)
なお、ラベル検出を行う場合は、追加料金を払うことなく「セーフサーチ」チェックも仕掛けることができます。これはアダルト画像などを検出するもので、上記の卓上クリップ扇風機の写真の場合は、以下のような結果になります。
"safeSearchAnnotation": { "violence": "VERY_UNLIKELY", "racy": "VERY_UNLIKELY", "adult": "VERY_UNLIKELY", "medical": "VERY_UNLIKELY", "spoof": "VERY_UNLIKELY" }
セーフサーチについては、以下のサイトに仕様が書かれています。 https://cloud.google.com/vision/docs/other-features#safe_search
一応計数してみましょう。
661種類、4917個ものラベル検出があったわけですが、この結果をどうやって取りまとめたものでしょうか?
一番単純な方法は、「ラベルごとにスコアを加算する」やり方です。これをサイト画像全体について集計すると、どんな画像が多いのかを摑むことができそうです。以下のような結果になりました。
url | label | score -------------------+-----------------+------------------ www.ra*****.co.jp | product | 249.13065277 www.ra*****.co.jp | font | 178.09255501 www.ra*****.co.jp | text | 174.66525343 www.ra*****.co.jp | line | 115.06299671 www.ra*****.co.jp | brand | 112.54623938 www.ra*****.co.jp | logo | 96.9688526700001 www.ra*****.co.jp | graphics | 87.28768391 www.ra*****.co.jp | black | 82.1643062 www.ra*****.co.jp | black and white | 79.13861794 www.ra*****.co.jp | monochrome | 54.89684521 (10 rows) url | label | score ------------------+-------------+------------- www.am****.co.jp | product | 203.6307481 www.am****.co.jp | font | 44.40389657 www.am****.co.jp | text | 32.15153994 www.am****.co.jp | brand | 30.75662519 www.am****.co.jp | technology | 22.13816894 www.am****.co.jp | line | 17.98218844 www.am****.co.jp | yellow | 13.99654375 www.am****.co.jp | black | 13.39340801 www.am****.co.jp | hardware | 12.35800936 www.am****.co.jp | sleeve | 12.21443735 (10 rows)
結果は両サイトでよく似ています。両サイトともリテールサイトですから、「product」や「brand」が上位に来るのは当然です。また、画像の中には商品画像だけでなく、Webサイト自身のフレームやアイコンも多量に含まれている他、商品写真にも文字が埋め込まれているものが多数あります。このため「font」「text」「line」や色名も共通で上位に入っています。
強いて傾向を指摘するとすれば、R社の「logo」と、A社の「technology」です。R社のサイトが企画サイトへのポータルサイトの機能を重視したデザインになっているのに対し、A社のサイトは家電の写真が大写しになっていました。このような大雑把なやり方でも、少しは両サイトの傾向の違いが出ていると言えるのではないでしょうか。とは言え、もう少しなんとかならないでしょうか。
次に思いついた方法は、サイトごと、各ラベルごとに1~100までの相対スコアを計算し、これを相互に比較する方法です。例えばあるサイトで最も合計スコアの高いラベルには100を、最も合計スコアが低いラベルには0を設定します。ラベルごとに突き合わせれば、片方のサイトで扱いの小さい(または無い)ラベルが他方のサイトでは大きく取り上げられている、などの傾向がわかるかもしれません。
この結果はなかなか興味深いものとなりました。以下に抜粋します。
description | r_rel_score | a_rel_score | rel_score_diff -------------------------------------------+-------------+-------------+---------------- bottled water | | 81 | -81 toy | 10 | 87 | -77 electronics accessory | 23 | 92 | -69 ... clothing | 93 | 94 | -1 ... product | 100 | 100 | 0 ... recipe | 90 | 10 | 80 hair coloring | 91 | | 91
今度ははっきり以下の傾向が見て取れます。
確かにA社のサイトには、ミネラルウォーターとおもちゃが多いのです。また両サイトとも衣料品がかなりのスペースを占めています。更に、この時のR社サイトには食材販売企画の広告が多く、これが「recipe」と認識されたと考えられます。 水とおもちゃ・家電重視のA社と、食品と美容重視のR社という傾向が、かなりはっきりと抽出されました。
今回は大手リテール業者のトップサイトのため、セーフサーチで問題が指摘された画像はほとんどありませんでした。 しかし、ただひとつ、 「adult = POSSIBLE」となった商品があり、それは「目元エステ家電」でした 。商品紹介画像では女性が仰向けになって分厚いアイマスクのような商品を装着していたので、誤解されてしまったようです。
しかしこの指摘、わからないでもありません。今回評価した画像の中ではこの画像以上に指摘されそうな画像はありませんでしたので、これはこれで正しい評価と言えます。
Cloud Vision APIは既成のモデルを使用しますので、ラベルの結果については受け入れるしかありません。 しかし、もう少し使い方のノウハウが蓄積できれば実用になりそうだ、というのが筆者の感想です。 既成AIサービスを効果的に使うには、それなりの経験を積む必要があるのかもしれません。
最後までお読みいただき、ありがとうございました。