# Trade-Offs Under Pressure - Chapter 4: Event Description > 前: [[@2015__MSc__Trade-Offs Under Pressure - Chapter 3 Research Design]] | 次: [[@2015__MSc__Trade-Offs Under Pressure - Chapter 5 Results]] | 全体: [[Trade-Offs Under Pressure]] ## 要約 第4章は、本研究が分析対象とする単一の事象、すなわち2014年12月4日に[[Etsy]]のサインイン済みホームページで発生した性能劣化を、時系列に沿って記述する章である。事象の文脈(Etsyの事業規模とホリデー商戦期という時期)、事象の経過(検知から根本原因の特定、緩和までの対応チームの動き)、事象を理解するために必要なドメイン固有の背景(システムアーキテクチャと典型的なリクエスト-レスポンスフロー)の3部構成を取る。分析や解釈は行わず、第5章(Results)以降で用いる素材としてのタイムラインを提示することに徹する(§Caveat of constructed narratives)。 ## 事象の文脈 Etsyはオンラインマーケットプレイスであり、「世界中の人々がオンライン・オフラインの両方でつながり、ユニークな商品を作り、売り、買う」場と説明される(About Etsy, n.d.)。2015年第2四半期時点で出品数は約3,200万点、アクティブな出品者数は150万、アクティブな購入者数は2,170万に上り、2014年の年間流通取引総額(GMV)は19.3億ドルであった。 12月は大半のeコマース企業にとってホリデーギフト商戦のため繁忙期にあたる。米国では感謝祭翌週の月曜日を指す「Cyber Monday」がオンライン購買活動を促すマーケティング用語として定着している。本研究が対象とする事象は2014年のCyber Mondayから3日後に発生した。Etsyは2014年第4四半期の決算で、2014年12月31日時点のアクティブ購入者のうち63%が同社マーケットプレイスにログインしたと報告している。 ## 事象の経過 ### 検知(1:06pm-1:18pm EST) 2014年12月4日1:06pm(Eastern Standard Time)、Etsy.comサイトの一部が利用不能になっているとの報告が、カスタマーサポート部門のテクニカル担当・Personalization Teamのプロダクトマネージャ・社内の他メンバーなど複数の経路から同時多発的に上がり始めた。通常、ログイン済みメンバーのホームページには、お気に入り登録した店舗の新着出品、友人のお気に入り、過去の行動に基づくレコメンデーションなどをパーソナライズして表示する「activity feed」がある。この事象では、パーソナライズドホームページの代わりに、パーソナライズされない汎用の「trending items」フィードが表示されていた。これはパーソナライズドホームページが構築できない場合にのみ表示されるコンティンジェンシー機能である。 偶然にも、Personalization/Homepage Team(プロダクトマネージャ・デザイナー・エンジニアで構成)はBrooklyn本社の会議室に集まっており、複数のエンジニアがビデオ会議で遠隔から接続していた。この集まりは、チームが新たに構想・設計・構築・ローンチしたパーソナライズドフィード機能について発表する「Lunch and Learn」セッションのためのものであった。発表開始から6分後、聴衆の一部が当該機能が動作していないことに気づいた。 チームメンバーはまずEtsy社内の#sysops IRCチャンネルで問題の診断と解決に着手し、本番システムの状態について様々な質問を投げかけ、診断的な観察を持ち寄り始めた。その後、複数のエンジニアが仮想的な議論を#warroomチャンネルへ移し、診断と解決に集中した。#warroomチャンネルでは、エンジニアたちが状況について複数の仮説を議論し、それぞれが気づいたグラフやチャートを共有・議論し、作業中の仮説を裏付ける・反証するための取るべきアクションを互いに提案し合った。 1:18pm、サインイン済みホームページのサブセクションである「サイドバー」を構成するために発行されるAPI呼び出し(Member_Homepage_Sidebar)にレイテンシの急上昇が見られる、との観察がなされた(Figure 4、Median and 90th percentile performance of the Member_Homepage_Sidebar API call)。 **Figure 4: Member_Homepage_Sidebar API呼び出しのレイテンシ** ![[_attachments/msc-allspaw-2015-tradeoffs-under-pressure/ch04-fig4-sidebar-api-latency.png]] (Figure 4. 17:50頃(米国東部時間換算で1:18pm付近)から、Member_Homepage_SidebarのAPI応答時間(中央値・90パーセンタイル)が約100msから急上昇し、18:05台には3,500msに達している様子を示すグラフ。) サイドバーには、ブログの注目ショップ・直近2件のブログ記事のリンクと写真・トップカテゴリへのURLリンクなど、ユーザーが関心を持ちうる付随コンテンツへのリンクが複数含まれる(Figure 5、サインイン済みホームページのスクリーンショットとサイドバー構成要素の位置)。 **Figure 5: サインイン済みホームページとサイドバー構成要素** ![[_attachments/msc-allspaw-2015-tradeoffs-under-pressure/ch04-fig5-signed-in-homepage-screenshot.png]] (Figure 5. サインイン済みホームページのスクリーンショットに、サイドバー全体・「featured shop」モジュール・「More from the blog」モジュールの位置を注釈で示す。) ### 緩和と原因追跡(1:18pm-1:36pm EST) チームには、サイドバーなしでホームページをロードできるようにする変更、すなわちエラーが発生していると見られるコードを無効化しつつページの残り部分は維持する、という提案がなされた。これはチームがこのようなシナリオのために事前に構築していたconfiguration featureであった。合意が得られた後、ProdEng2がこの設定変更の作業を開始した。 作業と並行して、チームメンバーはさらなる仮説を検討していたところ、InfraEng2がMember_Homepage_Sidebarリクエストのアプリケーションログの一行を#warroomチャンネルに投稿した(1:21:01pm)。 ``` [01:21:01 PM] <InfraEng2>: 10.101.152.3, 10.101.152.3, 10.101.160.45 - - - [04/Dec/2014:18:19:24 +0000] "GET /v3/public/shops/7887355/cards HTTP/1.1" 400 61 "/v3/member/23636811/homepage/sidebar" "Api_Client_V3/Member_Homepage_..." ``` このログはHTTPステータスコード400(Bad Request)の応答を示していた。InfraEng2は続けて、アプリケーションコード内で見つかる400ステータスコードのありうる定義を投稿した(1:21:25pm): `Input_MissingError`・`DataType_Exception_InvalidInput`・`EtsyORM_RecordValidationException`。InfraEng2はさらに400ステータスコードの他の発生例を調査した。 サイドバー関連のエラーは、ProdEng2がサイドバーを停止する変更をデプロイした時点で止まったが、サイドバーが有効な状態でなぜエラーが発生していたのか、またそのエラーがパーソナライズドホームページにどう影響していたのかは、チームにとって依然として不明であった。 観察と仮説の共有は続き、1:28pmには、特定のAPIメソッド(Public_Shops_GetShopCards)のエラープロファイルがサイドバーのエラーパターンと一致する、との報告がなされた(Figure 6、エンジニアが#warroomチャンネルで共有したログ解析ツールのスクリーンショット、エラーを示すAPIメソッドを示す)。 **Figure 6: #warroomチャンネルで共有されたログ解析ツールのスクリーンショット** ![[_attachments/msc-allspaw-2015-tradeoffs-under-pressure/ch04-fig6-log-analysis-tool-screenshot.png]] (Figure 6. Logstashのダッシュボードで、HTTP応答コード400のイベントをAPIメソッド名(`etsy_api_method_name`)で集計した結果。18:00頃から`Public_Shops_GetShopCards`(合計36,980件)のイベント数が急増しており、サイドバーのエラーパターンと一致するAPIメソッドとして特定された様子を示す。) 調査はこのAPIメソッドの挙動の詳細に焦点を移して継続され、1:32pmには、単一ショップのデータを求めるAPIリクエストがエラーを発生させていること、そしてそのショップIDのデータが存在しないことが判明した。当該ショップのオーナーのユーザーIDはEtsyの従業員のものであり、そのショップは過去に存在していたが「closed」状態にあることが分かった。 1:36pmには、このショップがブログからリンクされていること、そしてショップを所有するEtsy従業員がエラー発生時刻の頃にブログへ記事を投稿していたことが判明した。コンテンツチームのエンジニアに連絡が行き、当該ブログ記事は一時的に「unpublish」された。記事の著者にも問題について連絡がなされ、問題が完全に解決するまで別の記事を公開しないよう助言された。 ### 原因の仮説的機構 チャンネル内で問題の機構についてさらに議論が続けられ、以下の仮説的な連鎖が提示された。 - ブログ記事が公開され、その著者はあるショップIDと紐づいている。 - サインイン済みホームページのサーバコードは、サイドバーにデータを詰めるためのAPI呼び出しを行い、これにはブログ記事著者のショップIDが含まれる。 - ショップデータを求めてデータベースへの呼び出しが行われ、「存在しない」エラーが返され、サーバは400ステータスコードを返す。 - 400ステータスコードは、キャッシュサーバに対して空の結果をキャッシュしないよう指示する。これにより、そのデータに対する以降のすべてのリクエストが、毎回データベースへのクエリを発生させることになる。 - ショップに対する高頻度のリクエスト(サインイン済みホームページへのすべてのリクエストで発生)により、キャッシュサーバは受信リクエストをキューイングし始め、キューが十分に大きくなるとリクエストに3.5秒のレイテンシが生じる。 - 3.5秒のレイテンシはホームページコードが設定するタイムアウト値であり、これに達すると汎用・非パーソナライズドの劣化状態へフォールバックする。 サインイン済みホームページの主要機能(activity feed)が復旧した後、チームは因果機構をさらに検証するため、また400ステータスコードのエラーを適切にキャッシュするようアンダーレイングのコードを変更するまでの間、サイドバー内の「more from the blog」モジュールを夜通し無効化したままにすることを決定した。 ## ドメイン固有の背景 ### アーキテクチャ概要 事象に関与したシステムを読者に視覚的に示すため、研究参加者には自分が頭の中に描いているアーキテクチャの図を高レベルで描くよう依頼された。それらの図を合成した結果がFigure 7である。 **Figure 7: システムアーキテクチャと典型的なリクエスト-レスポンスフローの高レベル概要** ![[_attachments/msc-allspaw-2015-tradeoffs-under-pressure/ch04-fig7-architecture-request-response-flow.png]] (Figure 7. Etsyユーザーからのホームページリクエストが、Content Delivery Network(CDN)・webserverクラスタ・varnishを用いたcachingクラスタ・APIクラスタ・databaseクラスタ群を経由して応答が組み立てられ返される、典型的なリクエスト-レスポンスフローを参加者の認識をもとに描いた図。) ### 典型的なリクエスト-レスポンスフロー ユーザーがEtsy.comのログイン済みホームページをリクエストすると、そのリクエストはContent Delivery Network(CDN)を通過し、webserverのクラスタで受け取られる。webserverはvarnishソフトウェアを稼働させているキャッシュサーバのクラスタに対して任意の数のAPIリクエストを実行する。正確なリクエスト結果がキャッシュ内に見つかれば(キャッシュ「HIT」)、キャッシュサーバはデータを直接返す。これは性能・効率上の利点を与えることを意図している。リクエスト結果がキャッシュに見つからない場合、リクエストはAPIサーバのクラスタへ転送され、APIサーバはデータを保持する各種データベースクラスタから必要なデータを取得する。これらの結果は、応答がキャッシュクラスタを通過して戻る過程でキャッシュされ、webserverでユーザーのウェブブラウザが解釈できる応答へと整形される。 本事象では、webserverがAPIに対して行うMember_Homepage_Sidebarリクエストメソッドの呼び出しが、「More from the blog」モジュールにおける最新のブログ記事の著者に関してPublic_Shops_GetShopCardsリクエストメソッドの呼び出しを実行し、これがclosed状態であることが判明した、というものであった。APIメソッドはこれを「存在しない」と解釈し400ステータスコードを返し、それによってキャッシュサーバはその結果をキャッシュしないことになった。(通常、キャッシュサーバは「ネガティブ」な応答を既定でキャッシュしない選択をする。正典のデータソースが修正された後でもキャッシュされたエラー応答を返し続けるより、毎回正典のデータソースに戻る方がよいという前提に基づく。) 結果がキャッシュされないため、応答時間にレイテンシが加算され、新規リクエストのたびに全プロセスが繰り返されることになる。この応答時間の増加により、キャッシュサーバ内のプロセスがより長い時間ビジー状態を保つことになり、利用可能なプロセス数が限られているため、キャッシュソフトウェアの挙動として未処理のリクエストがキューイングされる。ホリデー期に多数のユーザーがログインしている状況下で、存在しないショップ情報を求めるリクエストがますます増加し、最終的にリクエストが積み上がって当該機能が使用不能とみなされるまでに至った。 ### 構成された物語であることについての留保 著者は本章で提示した記述について留保を付している。ここで提示されている内容は、事象の網羅的・客観的な記録を提供することを意図したものではなく(それは不可能である)、むしろ研究の焦点を位置づけ、分析やアプローチが乗るための土台を提供するために、選択された詳細と局面による高レベルなタイムラインを提示することを目的としている。 ## 関連 - [[Etsy]] — 本事象の当事者組織。EC マーケットプレイスの運営企業 - [[@2015__MSc__Trade-Offs Under Pressure - Chapter 3 Research Design]] — 本章が記述する事象を分析対象として選定した研究デザインの章 - [[@2015__MSc__Trade-Offs Under Pressure - Chapter 5 Results]] — 本章のタイムラインを診断・対応・協調のエピソードに分解して分析する章 - [[Trade-Offs Under Pressure]] — 本論文のハブページ ## 出典 - `.raw/theses/msc-allspaw-2015-tradeoffs-under-pressure/chapters/ch-04.txt`(PDF p31-36)