LoginSignup
11
5

More than 5 years have passed since last update.

aptpodAdvent Calendar 2018Day 22aptpod
@smith-30

go build -race でプログラムが遅くなってた話

Last updated at Posted at 2018-12-22

aptpod adventcalendar 2018の22日目です。
21日目は、弊社のiOSエンジニアが面白いデモをやってる記事なのでお時間ある方は是非。
ネタに困っていましたが、困ったことが運良く起こったので
それの反省を書こうと思います。

はじめに

goでは、goroutineを使うことにより簡単に並列処理が書けます。
ただ、下手に使うと競合状態を発生させ、プログラムの挙動が不定になったりします。1
要は、下記のように非同期処理による順序の問題で出力結果が異なったりしてしまうのです。

package main

import (
    "fmt"
    "time"
)

var count = 0

func incrementCount() {
    if count == 0 {
        fmt.Println("do increment")
        count++
    }
}

func main() {
    go incrementCount()
    go incrementCount()

    time.Sleep(200 * time.Millisecond)
    fmt.Printf("result: %v\n", count)
}

これは繰り返していると

do increment
do increment
result: 2

だったり

do increment
result: 1

します。(最初のスレッドがcount++をする前に後続のスレッドがif節をすり抜けるため)
このようなプログラマの意図しない処理結果を防ぐためにgoでは race detectorが提供されています。

弊社では、センサー値のような高頻度で発生するデータを処理するプログラムを書くことが多く
goroutineをうまく使いながらスループットの出せるものを作ることがよくあります。

race detector

race detectorは先に挙げた競合状態を検出してくれる代物です。
試しに使ってみましょう

$ go run -race race.go
o increment
do increment
==================
WARNING: DATA RACE
Read at 0x000001216840 by goroutine 6:
  main.incrementCount()
      /Users/aptpodmisu/go/src/github.com/smith-30/gopg/advca/race.go:13 +0xa7

Previous write at 0x000001216840 by goroutine 7:
  main.incrementCount()
      /Users/aptpodmisu/go/src/github.com/smith-30/gopg/advca/race.go:13 +0xc3

Goroutine 6 (running) created at:
  main.main()
      /Users/aptpodmisu/go/src/github.com/smith-30/gopg/advca/race.go:18 +0x46

Goroutine 7 (finished) created at:
  main.main()
      /Users/aptpodmisu/go/src/github.com/smith-30/gopg/advca/race.go:19 +0x5e
==================
result: 2
Found 1 data race(s)
exit status 66

このように DATA RACEが起こっていると教えてくれるようになります。
ちなみにバイナリにrace detectorを差し込むこともできて、下記は上記と同じ結果が起きます

$ go build -race race.go
$ ./race

ただし、-race　を入れて生成されたバイナリには検査用の処理が裏側で動くようになり
処理にもよりますが中々にスループットを奪います。
それをちゃんと理解してbuildを分けておかないと僕が体験した困ったことにつながります。

詳しくは公式を御覧ください

僕が困ってたこと

手元からビルドしたバイナリでの処理は早いのに
linux上のansibleからデプロイされたバイナリの処理が遅い、しかもメモリを4倍くらい食ってる.....

原因

手元のクロスコンパイルビルドでは -raceが無効になっていて
ansibleが使うビルドでは -raceが有効になっていたから

バイナリサイズが違うということは、一緒に作業をしてくださっていた強いエンジニアが指摘してくれましたが
どうにも思い当たる節がないので pprof を使って調べました

遅いバイナリ

(pprof) top 100 
Showing nodes accounting for 26.19s, 87.24% of 30.02s total
Dropped 392 nodes (cum <= 0.15s)
      flat  flat%   sum%        cum   cum%
    18.78s 62.56% 62.56%     18.78s 62.56%  runtime._ExternalCode
     1.74s  5.80% 68.35%      1.74s  5.80%  racecall
     0.68s  2.27% 70.62%      0.68s  2.27%  racecalladdr
     0.53s  1.77% 72.39%      0.53s  1.77%  time.Duration.Seconds (inline)
     0.46s  1.53% 73.92%      0.46s  1.53%  runtime.raceread
     0.33s  1.10% 75.02%      0.85s  2.83%  runtime.scanobject
     0.29s  0.97% 75.98%      1.27s  4.23%  <my-repository>/processor.(*TimeSeries).Drop
     0.26s  0.87% 76.85%      0.30s     1%  runtime.greyobject
     0.24s   0.8% 77.65%      0.24s   0.8%  runtime.racefuncenter
     0.23s  0.77% 78.41%      0.53s  1.77%  racefuncenter
.
.
.

早いバイナリ

(pprof) top100
Showing nodes accounting for 22s, 77.25% of 28.48s total
Dropped 364 nodes (cum <= 0.14s)
Showing top 100 nodes out of 173
      flat  flat%   sum%        cum   cum%
     1.48s  5.20%  5.20%      1.91s  6.71%  runtime.findObject
     1.20s  4.21%  9.41%      4.66s 16.36%  runtime.mallocgc
     1.15s  4.04% 13.45%      1.41s  4.95%  runtime.greyobject
     1.06s  3.72% 17.17%      3.57s 12.54%  runtime.scanobject
     0.99s  3.48% 20.65%      1.94s  6.81%  <my-repository>/processor.(*TimeSeries).Drop
     0.87s  3.05% 23.70%      1.08s  3.79%  encoding/json.stateInString
     0.84s  2.95% 26.65%      2.62s  9.20%  runtime.gcWriteBarrier
     0.77s  2.70% 29.35%      0.77s  2.70%  runtime.memmove
     0.75s  2.63% 31.99%      0.75s  2.63%  time.Duration.Seconds (inline)
     0.68s  2.39% 34.38%      1.77s  6.21%  encoding/json.
.
.
.

結果からどうにも _ExternalCode, racecall, racecalladdr がパフォーマンスに影響していそうですね
_ExternalCodeはネイティブの動的ライブラリに費やした時間らしいのですが
グラフ出してないのでどこからの呼び出しなのかはわかっていません2

しかし、racecall, racecalladdrが頻繁に呼ばれてることから race処理が遅いバイナリでは動いていて
早いバイナリでは動いてないことがわかりました。(これも強いエンジニアの方に指摘されたのですが汗)

そこから、build処理が手元とansibleでは違うということに気づき
raceが起きていないことを確認して、build処理からraceを外しました。

便利なオプションがあっても、ビルド後に想定どおりのパフォーマンスがでるのか、裏側で何が起こるか
しっかり調べとかないと、何がプログラムを遅くするのかわからないので気をつけようと思います(懺悔)

うまくつきあうために

  • -raceはテスト時や、ロングランなど動作検証時に留め、性能テストとは分けてつかう
  • build スクリプトはよく確認する

ちなみに

Rustだとコンパイル時点で弾いてくれたりしないかなと試しましたが
このように書けば最初のgoのコードと同じことは起こせました。
競合状態はプログラマが管理すべきなんでしょうね、気をつけます..

use std::{thread, time};

static mut COUNT: i32 = 0;

fn increment_count() {
    unsafe {
        if COUNT == 0 {
            println!("do increment");
            COUNT += 1;
        }
    }
}

fn main() {
    thread::spawn(move || {
       increment_count()
    });
    thread::spawn(move || {
       increment_count()
    });
    let millis = time::Duration::from_millis(200);
    thread::sleep(millis);
    unsafe {
        println!("result: {}", COUNT);
    }
}

rustではunsafeを使わないとmutableな値にアクセスできないので(そもそも変数宣言時にmutableだと教えないとダメ)
すごい悪いことをしてる気分にはなるので、自然と競合は防げるかもしれません。

  1. こちらがデータ競合、競合状態について詳しい ↩

  2. https://github.com/golang/go/wiki/Performance ↩

11
5
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
11
5