くらしのマーケット開発ブログ

くらしのマーケットを開発する、みんなのマーケットによる技術ブログ

Pythonでメモリ使用量を改善してみる

こんにちはエンジニアののりすけです。

みんなのマーケットではPythonを使用したサービスを動かしています。以前より使用メモリが異常に大きいサービスがあるため、SREチームからなんとかしてほしいとの依頼が来ています。

今回はサンプルコードを使ってPythonのメモリプロファイルを行いながら、省メモリなアプリケーションをどのように実装するか検証したいと思います。

利用するツール

  • memory_profiler
  • matplotlib

上記のライブラリをpip installでインストールしておきます。

memory_profilerの基本的な使い方

まず使い方を確認します。以下のように確認したい処理にデコレータ@profileを記述します。

from memory_profiler import profile


def large_integer_list():
    return [i for i in range(0,10000000)]


@profile
def main():
    result = sum(large_integer_list())
    print(result)

if __name__ == '__main__':
    main()

上記のコードを実行すると以下のような結果が出力されます。

$ python sample1.py
49999995000000
Filename: sample1.py

Line #    Mem usage    Increment   Line Contents
================================================
     8     12.4 MiB     12.4 MiB   @profile
     9                             def main():
    10     17.0 MiB      4.6 MiB       result = sum(large_integer_list())
    11     17.0 MiB      0.0 MiB       print(result)

左にあるMem usageが該当の行が評価された時点でのメモリ使用量、Incrementが評価された事による使用量の増加を表しています。今回の例の場合、listに入っている数字の合計を算出した時点で4.6MiB増えたことになっています。

この結果を少し考えたいと思います。

もともとの想定では大きなリストを作成し、メモリを大きく使うことを想定していましたが、このプロファイル結果では4.6MiBしか増えていないように見えてしまいます。しかし、よく考えるとこの部分はsum([int]) を評価した結果が+4.6MiBであり、sum関数を処理する上で不要になった情報は削除されていっているように考えられます。

今度は時系列に推移を見たいため、memory_profilermatplotlibを使って実行時のメモリ使用量を可視化します。

$ mprof run sample1.py
$ mprof plot

このようにmprofコマンドを利用するとグラフ化することができます。グラフから最大400MiB近くまでメモリを使用したことがわかりました。

f:id:curama-tech:20180621220646p:plain

次はこの400MiB近くまで使用してしまうこのコードを改善します。

メモリ使用量の改善

改善案としてlarge_integer_list()関数をリスト型ではなく、ジェネレータを返すように変更します。

from memory_profiler import profile

def large_integer_generator():
    # ここをGenerator式に変更
    return (i for i in range(0,10000000))


@profile
def main():
    result = sum(large_integer_generator())
    print(result)

if __name__ == '__main__':
    main()

実行結果

mprof run sample1.py
mprof: Sampling memory every 0.1s
running as a Python program...
49999995000000
Filename: sample1.py

Line #    Mem usage    Increment   Line Contents
================================================
     8     12.8 MiB     12.8 MiB   @profile
     9                             def main():
    10     12.8 MiB      0.0 MiB       result = sum(large_integer_generator())
    11     12.8 MiB      0.0 MiB       print(result)

f:id:curama-tech:20180621220837p:plain

今度はグラフ上もメモリ使用量が劇的に減っていることがわかります。ジェネレータを使うことで一度に大量のデータを確保することなく一つずつ処理しているため省メモリで処理することができます。

しかし、グラフのx軸を確認すると20秒を超える実行時間になっています。先程のリストを利用した場合は10秒を切る実行時間だったのに対して2倍以上遅い。。。

実行速度の改善

先程のコードではメモリの使用量は改善できましたが、今度は実行速度が問題になってしまいました。原因として考えられるのはジェネレータではyieldするたびに値の評価が行われます。評価回数があまりに多くなってしまったため速度が低下したことが考えられます。

上記の問題点を改善したコードが以下になります。

from memory_profiler import profile
# Iteratorに対する便利な関数がまとまったモジュール
from itertools import (islice, chain)

# iteratorをchunkサイズに分割する関数
def chunks(iterable, chunk_size):
    iterator = iter(iterable)
    chunk = tuple(islice(iterator, chunk_size))
    while chunk:
        yield list(chunk)
        chunk = tuple(islice(iterator, chunk_size))

def large_integer_generator():
    chunk_size = 10000
    # chunk毎にsumを行う
    for chunk in chain(chunks(range(0,10000000), chunk_size)):
        yield sum(chunk)

@profile
def main():
    result = sum(large_integer_generator())
    print(result)

if __name__ == '__main__':
    main()

実行結果

mprof run sample1.py
mprof: Sampling memory every 0.1s
running as a Python program...
49999995000000
Filename: sample1.py

Line #    Mem usage    Increment   Line Contents
================================================
    19     12.6 MiB     12.6 MiB   @profile
    20                             def main():
    21     15.0 MiB      2.4 MiB       result = sum(large_integer_generator())
    22     15.0 MiB      0.0 MiB       print(result)

f:id:curama-tech:20180621220855p:plain

前回のコードよりchunk分のメモリ使用量は増えていますが、速度が劇的に改善されました。

最後に

今回の検証ではうまくメモリ使用量/実行速度の改善を行うことができました。実際のサービスで同様に改善できる部分があるかは、これから確認しなければいけませんが、今後の実装においても良い検証ができたかと思います。

我々みんなのマーケットテックチームでは「くらしのマーケット」を一緒に作る仲間を募集しています!興味がある方はぜひ気軽に連絡ください (コーポレートサイト https://www.minma.jp/ ) 次回はエンジニアのカーキくんの予定です。

Varnish 503 Error

f:id:curama-tech:20180614114810p:plain

こんにちは、SREチームの千代田です。

サイトを構築するにあたって様々なミドルウェアを扱うことがあると思いますが、
今回はキャッシュサーバであるVarnishについてのお話です。

遭遇

私が入社して一ヶ月ほどたったとき、運用中のシステムで発生している既存のエラーについて学ぶ機会がありました。
話を聞きつつどのようなエラーが存在するのかを確認すると、以下のVarnishエラーを複数見つけました。

<!DOCTYPE html>
<html>
  <head>
    <title>503 Backend fetch failed</title>
  </head>
  <body>
    <h1>Error 503 Backend fetch failed</h1>
    <p>Backend fetch failed</p>
    <h3>Guru Meditation:</h3>
    <p>XID: 532316890</p>
    <hr>
    <p>Varnish cache server</p>
  </body>
</html>

このエラーの原因について既存のメンバーに確認すると、
複数ある特定のURLで起こる、POST/PUTのリクエストのbodyが短いと起きるなど諸説あり、発生原因はまだ特定できていないとのことでした。

調査

私はこの時Varnishに対して全く無知でした。
そのため、公式のドキュメントを頼りにトレースログを行うことにしました。

Varnishは高速で動作させるために、ログの出力をVSLと呼ばれる共有メモリセグメントに行なっています。
このログデータは一つのリクエストに対して大量の行数が出力されるため、日常的なログの出力を行っていませんでした。
膨大なログからデータを見つけるのはとても大変な作業のため、
このログをファイルに出力させつつ既存のログ側でエラーを検知した際に、
該当のVarnishログを見るといった方針で行なうことにしました。

そして、Varnishのログを取得することに成功しました。
VarnishのStateMachineについては、 公式を見ると分かりやすいと思います。

*   << BeReq    >> 576325623 
-   Begin          bereq 576325622 pass
-   Timestamp      Start: 1504590151.903285 0.000000 0.000000
-   BereqMethod    PUT
-   BereqURL       /v1/microservice/
-   BereqProtocol  HTTP/1.0
-   BereqHeader    host: xxx.yyy
-   BereqHeader    Content-Length: 4623
-   BereqHeader    accept: application/json
-   BereqHeader    content-type: application/json
-   BereqHeader    X-Varnish: 576325623
-   VCL_call       BACKEND_FETCH
-   VCL_return     fetch
-   BackendOpen    46 reload_YYYY-MM-ddWHH:mm:ss.backend_name x.x.x.x 80 x.x.x.x 56894
-   BackendStart   x.x.x.x 80
-   Timestamp      Bereq: 1504590151.903331 0.000046 0.000046
-   FetchError     http first read error: EOF
-   BackendClose   46 reload_YYYY-MM-ddWHH:mm:ss.backend_name
-   Timestamp      Beresp: 1504590151.907966 0.004681 0.004635
-   Timestamp      Error: 1504590151.907977 0.004692 0.000011
-   BerespProtocol HTTP/1.1
-   BerespStatus   503
-   BerespReason   Service Unavailable
-   BerespReason   Backend fetch failed
-   BerespHeader   Server: Varnish
-   VCL_call       BACKEND_ERROR
-   VCL_return     retry
-   Timestamp      Retry: 1504590151.907986 0.004701 0.000009
-   Link           bereq 577078686 retry

http first read error: EOFといったエラーが出ていることが確認できます。
このエラーについて検索するとstackoverflowやvarnishのmailing listなど、様々な媒体の情報が見つかりました。
しかしながら、どれを読んでも今回のエラーに対して思い当たる節がありませんでした。

また、Varnishからのリクエストを受けるDjangoのエラーログには以下のログが出力されていました。

django.http.request.UnreadablePostError: error during read(4623) on wsgi.input

こちらのエラーを確認すると、
先ほどVarnishから送ったリクエストに対してのContent-Length分のbody readに失敗したエラーに見えます。
この時点で私の中では、
バージョンの古いVarnishを利用していることによってバグでリクエストが破損しているのではないかといった結論に至りました。
そのため、後日Varnishのバージョンアップを行なうことにしました。

バージョンアップ後の調査

バージョンを上げたにも関わらず相変わらず503エラーが続いていました。
しかし残念ながら、別の仕事もある都合上いつまでも調査を行うわけにもいかず一度保留することにしました。

さらに数ヶ月後、手が空いた際に再度この問題に着手することができました。
前回の調査結果を念頭に置きつつ、今回は別のリクエストをパケットレベルで追うことにしました。
今回のリクエストは、以下の流れです。

BFF -> Varnish -> Microservice

まず始めにBFF -> Varnish間のパケットをtcpdumpで確認します。
余分なヘッダ/データを削っているため、lengthは若干異なります。

HH:mm:ss IP ip-xxx-xxx-xxx-xxx.40596 > ip-yyy-yyy-yyy-yyy: Flags [P.], seq 1:328, ack 1, win 211, options [nop,nop,TS val 1858274581 ecr 947885993], length 327
POST /v1/microservice2/ HTTP/1.0
Connection: close
Content-Length: 100
accept: application/json
content-type: application/json

{"xxxxxxxx":"XXX","xxxxxxxxxxxx":"XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX"}

この間は問題なく、データがきているように見えます。

次にVarnish -> Microservice間のパケットです。

HH:mm:ss IP ip-yyy-yyy-yyy-yyy.40324 > ip-zzz-zzz-zzz-zzz: Flags [P.], seq 1:260, ack 1, win 211, options [nop,nop,TS val 947885994 ecr 947921750], length 259
POST /v1/microservice2/ HTTP/1.0
Content-Length: 100
accept: application/json
content-type: application/json
X-Varnish: 888442338

リクエストは送られてきましたが、Content-Length分のbodyがありません。
しかしながら、Varnishのリクエストが503だった場合にretry処理を呼ぶようにしてあります。
今度はそちらのリクエストを確認しました。

HH:mm:ss IP ip-yyy-yyy-yyy-yyy.46642 > ip-zzz-zzz-zzz-zzz: Flags [P.], seq 247:606, ack 38176, win 843, options [nop,nop,TS val 947885994 ecr 947945014], length 359
POST /v1/microservice2/ HTTP/1.0
Content-Length: 100
accept: application/json
content-type: application/json
X-Varnish: 888672061

{"xxxxxxxx":"XXX","xxxxxxxxxxxx":"XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX"}

再送されたリクエストにはbodyがありました。
lengthも259 -> 359へとContent-Length分増えていることが分かります。
この時点で、VarnishによってPOSTのbodyが存在したりしなかったりすることが分かりました。
しかし残念ながら、なぜbodyが消えてしまうのかまでは今回の調査では分かりませんでした。

おわりに

Backendとの相性が悪いのかを確認するために、uWSGIを辞めてGunicornに変えるなど試しましたが、
相変わらず503エラーが起こったため、少なくともバックエンド起因ではないと考えています。
また、次のブログを参照し、
varnishでbackendのapacheにPOSTしているときにたまに(1/1000ぐらい)503 Service Unavailable になる現象はpassをpipeに変えたら出なくなった
実際に、Varnishのpassをpipeに変えれば、POST/PUTによる503が出なくなることの確認が取れました。
そのため、根本的な解決とはいかず不完全燃焼ですが、今回の調査をもって一旦解決とすることにしました。

最後までお読みいただき、ありがとうございました。
今回の問題に対して他のアプローチを思いつく方や、
システムへの調査/改善/開発など多岐に渡る業務を行いたいと思っている方がいらっしゃれば、
ぜひ一度オフィスでお会いしましょう

次回は、エンジニアののりすけさんの予定です。

あの日呼び出したモジュールの名前を僕達はまだ知らない

はじめに

みんなのマーケットで iOS / Android アプリエンジニアとして働いているYangです。

非常に分(意)か(味)り(不)や(明)す(!)く(!)タイトルに書いた通り、今回はデカップリングを話題として、Androidのモジュール化を紹介したいと思います。

モジュール化とは

イメージとしては:

f:id:curama-tech:20180608115351j:plain

(モザイク除去はこちらへ画像の出典)

違う!

複雑で巨大なシステムやプロセスを設計・構成・管理するとき、全体を機能的なまとまりのある“モジュール”に要素分割すること。設計・製造時の擦り合わせ作業をできるだけ少なくするために構成要素(部品)の規格化・標準化を進め、その相互依存性を小さくすることをいう。出典

「wwwの生みの親」「Webの父」などの異名を持つ、ティム・バーナーズ=リーさんの本「Principles of Design」に以下の名言があります。

Principles such as simplicity and modularity are the stuff of software engineering; decentralization and tolerance are the life and breath of Internet.

会社の事業拡大と共に、アプリの機能もどんどん増えて、複雑になっています。

巨大とまではいかなくてもビルドに時間はかかるし、ファイルツリーがだんだん長くなって、開発もしづらく、依存が多すぎて単体テストが書きづらいです。また、部分的な不具合や変更が発生したときに、その影響が全体へと波及してしまいます。

解決しないといけないこと

1. コードのデカップリング(分離原則)

 どうやって一つの巨大のプロジェクトを複数のモジュールに分けられますか。もしモジュール間で、再度お互いに直接アクセスするのであれば、デカップリングとは全く言えません。どうすれば直接の参照を避けられるでしょうか。

2. 各モジュールの独立実行

 一回のデバッグにもし一つか二つぐらいのモジュールだけ参加させたら、ビルドの時間は大幅に短縮できますから、開発の段階でどうやって最低限必要なモジュールだけをコンパイルさせますか。各モジュールが疎結合であれば,どうやって独立に実行やデバッグをさせますか。

3. 各モジュール間のデータ通信

 各モジュールは外部へのサービスを提供することができますが、メインモジュール(Host)や他のモジュールへどうやってデータを送受信すればいいでしょうか。

 実際画面遷移の本質も特殊なデータ送信ですが、Android上の画面遷移は Intent を使わないといけないので、解決の方法は少し違います。

コードのデカップリングの解決

巨大なコードを分割しやすくするために、Android Studio IDEに Multiple Module という機能をサポートしていて、これを使って最初に簡単な分離はできます(つまり参照が複雑なところは自分で整理しないといけないです)。

ここで明確したい概念があって、モジュールは二種類に分けることができます。

一つは Base Library で、これらは他のモジュールから直接参照できます。例えば、ネットワークモジュールや画像処理モジュールは二つの Base Library として考えられると思います。

もう一つは Component と似ているような感じで、完全な機能を持っています。くらしのマーケットのアプリを例にすると、予約モジュールやチャットモジュールは二つの Component と呼ばれたらいいです。

Base Library は単純に汎用的なサービスを提供するため、 モジュール化 に言った モジュール は基本的に二つ目です。

これで、コードの分離は図の通りにできます。

f:id:curama-tech:20180608115345p:plain

矢印を書いているところだけ依存関係が存在して、つまり Reservation ModuleCalendar Module はお互いに見えないです。こうすると、コードのデカップリングを実現できます。

各モジュールの独立実行の解決

ビルドツールに対して、あるモジュールがプロジェクトの入り口かどうかの判断は該当モジュールの build.gradle を参照しています。

apply plugin: 'com.android.library' の場合は部品で、 apply plugin: 'com.android.application' の場合はアプリと識別されます。

つまり一個 isRunAlone の変数を用意すれば、切り替えは可能です。

これ以外、アプリと識別された場合、 AndroidManifest.xml ファイルに最初ページとしての Activity も指定する必要があります。私の解決方法では二つのManifestファイルを用意して、リリースの際にdebug用のファイルを除外します。

最後、アプリとして実行するために必要な applicationId も指定して、独立実行の準備はできました。

if (isRunAlone.toBoolean()) {
    apply plugin: 'com.android.application'
} else {
    apply plugin: 'com.android.library'
}
// ......
    defaultConfig {
        if (isRunAlone.toBoolean()) {
            applicationId "jp.curama.shop.module1"
        }
    // ......
    }
// ......
    sourceSets {
        main {
            if (isRunAlone.toBoolean()) {
                manifest.srcFile 'src/main/debug/AndroidManifest.xml'
            } else {
                manifest.srcFile 'src/main/release/AndroidManifest.xml'
                java {
                    exclude 'debug/**'
                }
            }
        }
        // ......
    }
// ......

各モジュール間のデータ通信の解決

前書いた通り、ここは二つのシーンがあって、①画面遷移と②メソッド呼び出しです。色々調べて、一番良い解決案はAlibabaが提供している Open Source Library ARouter です。一発で二つのシーンを解決できます。

Android の標準画面遷移は下の通りです。ここでの問題は、 ActivityAActivityB をインポートしないと遷移できません。

// filePath: module1/ActivityA.kotlin
// module2への依存が発生してしまいました
import module2.ActivityB

class ActivityA: BaseActivity() {
    fun navigateToB(id: String) {
        val intent = Intent(this, ActivityB::class.java).apply { putExtra("id", id) }
        startActivity(intent)
    }
}

// filePath: module2/ActivityB.kotlin
class ActivityB: BaseActivity() {
    override fun onCreate(savedInstanceState: Bundle?) {
        super.onCreate(savedInstanceState);
        val id = intent?.getStringExtra("id")
        // ......
    }
}

ARouterを使う場合、 ActivityA は遷移先の URL がわかったら遷移できます。私達のシステムでは管理上の考えによって、 RouterPath という URL の集約ファイルを作って、 Base Business Layer に置いて、 URL のハードコードを避けました。またどの画面がどのURLを使っていて、必要なパラメーターが何であるかは誰でもすぐに一目瞭然で、把握できます。もう一つ便利なところは ARouter 経由で渡したパラメーターがインジェクターによって自動的に遷移先へアサインされるところです。

// filePath: module1/ActivityA.kotlin
// import ActivityB は不要です
class ActivityA: BaseActivity() {
    fun navigateToB(id: String) =
        ARouter.getInstance().build("module2/b").withString("id", id).navigation()
}

// filePath: module2/ActivityB.kotlin
@Route(path = "module2/b")
class ActivityB: BaseActivity() {
    @Autowired
    lateinit var id: String

    override fun onCreate(savedInstanceState: Bundle?) {
        super.onCreate(savedInstanceState);
        ARouter.getInstance().inject(this);
        // ここから this.id はもう使えます
        // ......
    }
}

シーン②も似たやり方で、 URL でアノテーションをして、使用者はインタフェースに依存することで、ARouterから実現を取得して、使ったらうまく動けます。

これでモジュール化の大きい問題を全部解決できました。

最後に

我々みんなのマーケットテックチームでは「くらしのマーケット」を一緒に作る仲間を募集しています!どんな環境で開発しているかはこちらの記事にまとまっています。興味がある方はぜひ気軽に連絡ください (コーポレートサイト https://www.minma.jp/

次回は、SREチームの千代田さんの予定です。

本番サーバーが結構な頻度で再起動を繰り返していたのでNode.jsのメモリ調査をしてみた話

みんなのマーケットでwebエンジニアとして働いている高橋です。

前回の記事(http://tech.curama.jp/entry/2018/02/23/120000)で、弊社ではNode.jsを使用しているという話を簡単にしましたが、今回はその運用中に出てきたトラブルシューティングの話をしたいと思います。

弊社ではマイクロサービス用のBFF(Backends For Frontends)としてNode.jsを採用しています。 ところが最近、弊社SREから、「Nodeサーバーの再起動が多すぎます。メモリが増えた時に再起動で解決するんじゃなくて、ちゃんとリークしないように最適化してください」というお願いがありました。

また、こちらの記事には、

As leaks grow, V8 becomes increasingly aggressive about garbage collection, slowing your app down.

とありますので、メモリリークを再起動で回避し続けることには、問題がありそうです。というわけで、実際にヒープダンプを取ってメモリ周りの調査を行ってみることにしました。(対処法については、主に*1を参考にしました。)

サーバーのメトリクス

まずは本番サーバの状態を見てみます。弊社ではgrafanaを用いてcpu使用率やメモリ使用量を可視化しています。今回問題があるサーバの状態を見てみると、f:id:curama-tech:20180523200256p:plainのように、数十分おきにメモリ量が変動していることがわかります。定期的にメモリ使用量が減っているのは、Node.jsのプロセスマネージャであるPM2によって、メモリが増えた場合にプロセスの再起動を行うように設定していたためです。

ローカル環境で挙動の確認

次にローカル環境で挙動を確認してみます。PM2にはpm2 monitというモニタリング用のコマンドがあります。これを実行しながらリクエストを投げてみると、 1リクエストあたり数MBから数十MBメモリ使用量が増えることがわかりました。また、リクエストのない状態にしてからメモリ使用量のベースラインに戻るまで、30sから60s程かかりました。また、リクエストを繰り返すと、ベースラインが次第に上がっていくことも観測できました。

強制ガベージコレクションを行ってみる

Node.jsは、--expose-gcフラグを付けて起動することによって、global.gc()として、ガベージコレクションを手動で実行することができます。試しに手動でこれを実行してみました。

状態 メモリ使用量
ベースライン 85MB
リクエスト10回実行 111MB
ガベージコレクション実行後 108MB

ですが、ガベージコレクションによって、たった3MBしかメモリ使用量が減少していません。この時点で、メモリリークが発生している可能性が示唆されました。

メモリリークの調査をしてみる

リークの調査には、まずはじめにmemwatch-nextを使用しました。

npm install memwatch-next

した後、

import * as memwatch from "memwatch-next";

memwatch.on("leak", info =>  {
    console.log("leak! ☔", info);
});

memwatch.on("stats", stats =>  { 
    console.log("stats! 📺", stats);
});

const hd = new memwatch.HeapDiff();
setInterval(() => {
    const diff = hd.end();
    console.log(diff);
}, 1000);

のようにして、ガベージコレクションのイベントが発生した場合にヒープのログを見ることができます。

この時点で手動でガベージコレクションを発生させると、

0|www      | stats! 📺 { num_full_gc: 2,
0|www      |   num_inc_gc: 19,
0|www      |   heap_compactions: 2,
0|www      |   usage_trend: 0,
0|www      |   estimated_base: 75128928,
0|www      |   current_base: 75128928,
0|www      |   min: 0,
0|www      |   max: 0 }

のようなログをコンソールから見ることができます。

更に試しに、

class Fuga {
    private foo: string[];
    constructor() {
        process.stdout.write("⏳");
        this.foo = [];
        for (let i = 0; i < 1000; i++) {
            const data = Math.random().toString();
            this.foo.push(data);
        }
    }
}

var leakyData: Fuga[] = [];

const hoge = () => {
    leakyData.push(new Fuga());
};

setInterval(() => {
    hoge();
}, 1);

のようにglobalから参照可能なオブジェクトに大量にデータを詰め込むと、

leak! ☔ { growth: 1374330784,
  reason: 'heap growth over 5 consecutive GCs (1m 4s) - -2147483648 bytes/hr' }

というように、leak時の警告を見ることができます。

ここまで仕込んでから、ローカルのサ−バーに対して

 while true; do curl localhost:3000; sleep 1s; done

として1sおきにリクエストを投げてみます。

しかし、ローカルサーバーではleakイベントが発生しませんでした。

次に、ヒープダンプのリクエスト毎のdiffを確認します。

ローカルのサーバーに対して数回リクエストを送り、new memwatch.HeapDiff();を利用したdiffを見てみると、

0|www      | { what: 'Code',
0|www      |   size_bytes: 527632,
0|www      |   size: '515.27 kb',
0|www      |   '+': 2448,
0|www      |   '-': 1510 }
0|www      | { what: 'Array',
0|www      |   size_bytes: 244784,
0|www      |   size: '239.05 kb',
0|www      |   '+': 8233,
0|www      |   '-': 6538 }
0|www      | { what: 'String',
0|www      |   size_bytes: 52816,
0|www      |   size: '51.58 kb',
0|www      |   '+': 1030,
0|www      |   '-': 386 }
0|www      | { what: 'Closure',
0|www      |   size_bytes: 11592,
0|www      |   size: '11.32 kb',
0|www      |   '+': 217,
0|www      |   '-': 55 }
0|www      | { what: 'Object',
0|www      |   size_bytes: 7944,
0|www      |   size: '7.76 kb',
0|www      |   '+': 453,
0|www      |   '-': 279 }

Codeというオブジェクトが最もサイズが大きいことがわかりました。

これは、v8で定義されており、「コンパイル済みのコードに関連するすべてのオブジェクトです」ということです。

このオブジェクトはJITで生成されるものなので、アプリケーション固有のものではありません。ですので次に、より詳細なヒープの内容を追うことにしました。

詳細なヒープダンプを取得する

詳細なヒープダンプを取得するために、nodeを--inspectオプション付きで起動します。

すると、

chrome-devtools://devtools/remote/serve_file/xxxxx

というリンクがコンソールに表示されるので、chromeでそのURLにアクセスします。

その後、Profilesタブから、Take Heap Snapshotを選択すると、ヒープダンプが取得できます。

試しに、

a) 初期状態
b) 5回リクエスト
c) 5分後

としてダンプを取得してみました。ここから、Summary -> Comparisonと選択し、ヒープのdiffを取ることができます。

詳しいダンプの見方はこちらです。

この結果、動かしていたアプリケーションのダンプの中で、リクエストに応じて増え、ガベージコレクトされないオブジェクトを特定することができました! (具体的には、利用していたDependency Injection用のパッケージが原因でした)

f:id:curama-tech:20180530111246p:plain
犯人

最後に

以上のようにして、Node.jsのメモリ調査をしてみました。今までNode.jsのガベージコレクションの仕組みを意識することがなかったので、知見が溜まってよかったです。

(次回はアプリエンジニアのヤンさんの予定です!)

みんマのいろんな部署を経てテックチームにきてよかった話

こんにちは!みんマテックチームのめぐみです。

社内では会社名と運営しているサービスのことを略して
会社名:みんなのマーケットのことを→「みんマ」
運営しているサービス:くらしのマーケットのことを→「くらマ」
と呼んでいます。この記事では略して書いていきます。


(くまモンと仲良し感のある猫の写真に最近癒されています)

私はみんマで働いて2年半、そのうちテックチームで働いて1年です。テックに入る前までは採用担当、コンサル、ちょっとマーケの業務をしていました。

今はテックチームでカテゴリーマネージャーをやっています。仕事している上で、いろんな部署で働いていたことがあってよかったと感じることがあるのでその話をしていきます。

ところで、カテゴリーマネージャーとはなにか?

くらしのマーケットにはハウスクリーニング系カテゴリやリフォーム系カテゴリなど、200個近いカテゴリが存在しています。そのうち、私はリフォーム系カテゴリの流通額を増やすことにコミットしています。 このままだとわかりにくいので、仕事内容をちょっと紹介します。

カテゴリーマネージャーの仕事をちょっと紹介

他部署で働いていたことの何がよかったのかを話す前に、カテゴリーマネージャーとしてやっていることの一部を紹介します。 最終的には流通額をあげることをゴールに置いていますが、まずは課題と感じていたコンサルティング業務の業務改善から進めています。

コンサルティング業務の効果の見える化

みんマには、くらしのマーケットに出店している出店者の売上をあげるためにアドバイスなどをするECコンサルタントがいます。しかし、実際のところコンサルティングしている内容がどれくらい実行されたか、また売上に貢献したかというのが今まであまり可視化されていませんでした。 そこでコンサルティング結果の見える化と、効果のあるコンサルティングの再現性を高くすることを目的に効果測定を開始しました。

コンサルティング業務の改善

効果測定の結果わかったことをもとに、下記を行いました。

  • 新しいコンサルティング方法を導入(オンラインコンサルティング)
     なぜ提案が実行されないのか?どういう時だったら実行度が高いのか?を分析した結果、導入を決定しました。導入後の結果についてはまだ導入したばかりなのでこの記事では触れません。

  • 売上アップに繋がらない業務の排除
    出店者の売上をあげるために存在しているコンサルタントですが、だんだんとそれ以外の業務が増えてきてしまったので、売上アップに直接繋がらない業務は排除しました。

  • 提案の実行度が高い出店者からコンサルティングできるように改善
    まず提案するべき相手はやる気がある相手、ということで提案する店舗のリストを作成

これらを進める上でいろんな部署での経験があってよかった話

  • ここでコンサルティング業務をしたことがあってよかった話

    • 業務内容を理解している(何のために、どれくらい時間がかかるのかも)
    • 提案の実行度がわからないor低い課題を肌感を持って知っていた

    やったことないと机上の空論になってしまったり、または考えた解決策が根本的に解決しないものであったりするなと思いました。

  • ここでSQLをちょっと使えてよかった話
    コンサルティング結果の見える化をするにあたり、SQLを使っています。 どういうデータを取得したいのかを明確にして、効果測定が私だけで完結してできることがよかったです。 1日に数十件コンサルティングしていますが、例えば出店者が画像を追加した履歴とコンサルタントが接触した履歴を元に効果のある提案だったかを出しています。

今後やること

  • 担当しているリフォームカテゴリの動向をもっと追い、カテゴリ特有の問題点を把握する
  • 売上金額にするとどれくらいのインパクトがあるのか?についてはまだ関係性を出せていないので、そこは今後の課題です。
  • 分析をもっと早くできるようになるのと自動化していく

伝えたいこと

ここまで、カテゴリーマネージャーの仕事についても知ってもらいたいと思って書きました。
私たちテックチームでは「くらしのマーケット」を一緒に作る仲間を募集しています!
様々なバックグラウンドをお持ちの方、新しいことにチャレンジしてみたいという方!ぜひ一緒に働きたいです!経験を活かす方法を一緒に考えましょう! 興味がある方はぜひお気軽にコーポレートサイトからご連絡ください。

おまけ

最近はボードゲームにはまっています!
テックチームだけではなく、他の部署のメンバーも一緒にやっています。一緒にできる方もお待ちしています〜!

ではまた来週!次はへいへいさんがお届けします!