アルパカログ

まじめなことを書きます。

チームリーダーを経験して感じた不安など

開発チームのリーダーになって2年半が過ぎ、それだけやっていると一通りのことは経験した気になってきます。

普段あまりこういうことは書かないし言わないのですが、このあたりでいったん私がこれまで感じた不安についてまとめておくことで、将来チームリーダーになる方々の心の準備になれば良いと思っています。


リーダーになって初めの1年ほどはエンジニアの上長で、実質的にはお守り付きみたいなものだったため、これといった不安もなく、いろいろなことにまだ気がつかない時期でもありました。

ほどなくして組織変更があり、非エンジニアの上長になりました。下記に挙げる3つの不安は、この独り立ちしなくてはならない期間に感じたものであります。

1. 業務内容の変化による不安

最初に訪れたのは、業務内容の変化から来る不安でした。以前の私は業務時間のほとんどを開発に充ててきました。今思えば、開発に集中できるように上長が環境を整えてくれていたのだとわかります。

他部署からの相談や依頼、メンバーのアサインとフォロー、上長への報告や資料作りなどといった開発以外の業務が次から次へとやってきて、気付けば開発に集中できる環境が無くなっていました。

開発し、技術を磨き、与えられた仕事に対して結果を出すというのが仕事のサイクルだったのに、開発に充てる時間が大幅に減ってしまったことで、どう結果を出したら良いかわからなくなってしまったのです。

2. 先の見えないキャリアに対する不安

業務内容の変化に慣れてくると、今度はキャリアに対する不安が首をもたげてきました。

チームは業界でも珍しいCS部門専属の開発チームです。業務範囲はCSのための管理ツールの開発、問い合わせフォームの保守や不正対策など幅広く、やりがいがある一方で、将来的に需要があるのかという点が不透明でした。

社内の近しいCSの人たちには、いてくれて本当に助かると言ってもらえる反面、「需要がないから他社には部門がないのでは?」と思ったりもしました。

イベントに参加して他社の人々と交流したり、偉い人の話を聞いたりして、ようやく私自身でキャリアを切り拓いていかねばならないという事実に行き着きました。

この気付きが、次に挙げる「チームメンバーの将来を負う不安」へと発展していくことは、想像に難くないでしょう。

3. チームメンバーの将来を負う不安

キャリアを切り拓くというのは、究極形としてCS業界でかの有名な山田さんがメルカリの執行役員に就任されたり、はてなのセールスエンジニアだった a-know さんが、業務が多岐に渡るに連れ自身の取り組みと組織をCREという名称を使って再定義されたりといったように、こんな道があるんだよというのを身をもって示すことだと思っています。

私もチームメンバーに対して道を示さなければなりません。

今の職種で食べていけるのか、3年後や5年後どんな技術や経験が必要とされているのか、どんな経験をしていただくと良いのか、それに対して私ができることは何か、いつか答えに辿り着くと信じて今もなお悩み続けています。


楽しい内容ではなくなってしまいましたが、もちろんリーダーになって嬉しいこともあります。

チームやメンバーが褒められたり、メンバーの成長が見えると、嬉しいですしやりがいを感じます。

加えて、これだけ思いやりがあって優れたメンバーと仕事ができることは一生涯ないんじゃないかと思えるくらい、素晴らしいチームで過ごせている今は本当に幸せなことだと思っています。

zen_ex という Elixir の Zendesk REST API ライブラリを公開しました

zen_ex という Elixir 向け Zendesk REST API ライブラリを公開しました。

zen_ex は Model と Entity からできていて、Model の各関数が Entity の struct を返すようになっています。

使い方は下記のように直感的で簡単です。

iex> alias ZenEx.Model
iex> alias ZenEx.Entity.{User,Ticket}

iex> Model.Ticket.list
[%Ticket{id: xxx, ...}, %Ticket{id: xxx, ...}, ...]

iex> user = Model.User.create(%User{name: "おとよ", email: "otoyo@xxx.xxx"})
%User{name: "おとよ", email: "otoyo@xxx.xxx", ...}

iex> ticket = ZenEx.Model.Ticket.create(%Ticket{subject: "チケットタイトル", description: "チケット本文", requester_id: user.id})
%Ticket{subject: "チケットタイトル", description: "チケット本文", requester_id: user.id, ...}

まだまだ開発途上なのでバグなどありましたら気軽に Issue や PR でお知らせいただければと思います。

Zendesk REST API で複数のチケットフィールドを指定してチケットを検索する

3年前から業務で Zendesk App を作っています。 Zendesk は開発者向け機能が豊富に提供されているところが良いですね。

今日は Zendesk REST APISearch API を使い複数のチケットフィールドを AND 指定してチケットを検索する方法について説明します。が、 Undocumented な方法のため使用は自己責任でお願いしますね。

リクエスト URL

チケットを検索する場合のリクエスト URL は下記のようになるでしょう。

/api/v2/search.json?query=type:ticket {query}&sort_by={sort_by}&sort_order={sort_order}&page={page}

チケットフィールドを含め検索条件は query で指定します。

チケットフィールドの指定

チケットフィールド (カスタムフィールド) の条件は Zendesk Support search reference にあるとおり fieldvalue:12345 のように指定します。

ここで気を付けなければならないのは 12345 の部分は ID ではなく値であるということです。

AND 条件

fieldvalue:12345,67890 のようにスペースを入れず CSV で指定します。


最近は過去に App Framework v1 で作った Zendesk App を v2 に書き換えて少し知見が溜まったので、また気が向いたら書きたいと思います。

logrotate されたログファイルを reopen する

あるデーモンプロセスのログが消えていることに気付きました。
厳密には、 restart した日はログがあるのに、日付が変わってからのログが空っぽなのです。
ログが消えるのは開発者にとって悪夢です。折しも障害発生なんてことがあれば…恐ろしくて想像したくないですね。
今日はデーモンプログラムのログを logrotate によりローテーションさせたときに発生する問題とその解決策についてお話ししたいと思います。

logrotate

logrotate の挙動は、現在のファイルをリネームし元のファイルと同名のファイルを作成するというものです。
例えば sample.log というログファイルをローテーションすると、sample.logsample.log-20160305 にリネームされ (dateext 指定時)、新たに sample.log という名前のファイルが作成されます。
logrotate の設定は /etc/logrotate.conf もしくは /etc/logrotate.d/ 以下に記述します。
試しに下記の内容で /etc/logrotate.d/sample を作成してみましょう (vagrant 部分はご自身の環境に置き換えてください)。

/home/vagrant/sample.log {
    missingok
    daily
    dateext
    create 0755 vagrant vagrant
    rotate 5
}

対象となるログファイルも作成しておきましょう。

$ touch /home/vagrant/sample.log

d オプションで設定ファイルをデバッグすることができます。

$ sudo logrotate -d /etc/logrotate.d/sample 
reading config file /etc/logrotate.d/sample
reading config info for /home/vagrant/sample.log 

Handling 1 logs

rotating pattern: /home/vagrant/sample.log  after 1 days (5 rotations)
empty log files are rotated, old logs are removed
considering log /home/vagrant/sample.log
  log does not need rotating

f オプションで即時にローテーションさせることができます。

$ sudo logrotate -f /etc/logrotate.d/sample

sample.log-20160305 のようなファイルが見つかるでしょう。

logrotate されると logger はどこに書き込むか

話を戻して、デーモンプロセス内の logger が sample.log を開いている状態で logrotate するとどうなるのでしょうか?

Ruby の pry を使って観察してみましょう。

$ gem install pry
$ pry

logger を使って書き込んでみます。

logger = Logger.new "sample.log"
logger.info "It's great log!"

sample.log に書き込まれていることがわかります。

$ cat sample.log
I, [2016-03-05T18:57:25.920004 #18403]  INFO -- : It's great log!

次に logrotate してみます。

$ sudo logrotate -f /etc/logrotate.d/sample

再度書き込んでみます。

logger.info "Where is rotated log?"

空っぽです。

$ cat sample.log

元のファイルに書き込まれていました。

$ cat sample.log-20160305
I, [2016-03-05T18:57:25.920004 #18403]  INFO -- : It's great log!
I, [2016-03-05T18:58:16.273417 #18403]  INFO -- : Where is rotated log?

ログファイルを open してからリネームされたので当然と言えば当然ですね。

どうやってログファイルを reopen するか

File だと File#reopen でファイルを開き直すことができますが、 Logger の場合はどうすれば良いのでしょうか?

方法は2つあります。
1つは ObjectSpaceFile オブジェクトを片っ端から reopen する方法で、 Unicorn で採用されています (*1)。 もう1つは Logger を継承するなどして logdev アクセサを追加し、 logdev.dev に格納されている File オブジェクトに対し reopen する方法で、私が考えました (どうでもいい)。
open_or_reopen はファイルの存在チェックをして存在しない場合は open, 存在する場合は reopen と読み替えてください。

ObjectSpace を使う方法

ObjectSpace.each_object(File) { |f| f.open_or_reopen if is_log?(f) }

すべての File オブジェクトを取得するので、ログファイルであることを確認する必要があります。

logdev アクセサを使う方法

class MyLogger < Logger
  attr_reader :logdev
end

logger = MyLogger.new "sample.log"
logger.logdev.dev.open_or_reopen

Ruby 2.3.0 以上の場合は LogDevice#reopen (*2) が使えます。

デーモンに logrotate を通知するには

ログファイルを reopen する方法はわかりましたが、デーモンとして実行中のプロセスに logrotate されたことを通知するにはどうすれば良いのでしょうか?

logrotate には lastaction/endscript というディレクティブがあり、すべてのログファイルがローテーションされた後に実行されるコマンドを記述することができます。
つまり lastaction/endscript ディレクティブでデーモンプロセスに対してシグナルを送り、デーモン側ではシグナルを受け取ったらログファイルを reopen すれば良いというわけです。

SIGUSR1 を trap してログファイルを reopen する下記のようなプログラム sample_daemon.rb を作成し、デーモンに見立てて動作を見ていきましょう。
このプログラムは5秒毎に現在時刻をログファイルに書き出します。

require 'logger'

File.open("sample_daemon.pid", "w") { |f| f.write "#{Process.pid}" }

class MyApp
  def self.logger
    @@logger ||= Class.new(Logger) { attr_reader :logdev }.new "sample.log"
  end
end

trap("USR1") do
  logger = MyApp.logger
  logger.logdev.dev.reopen logger.logdev.filename
end

loop do
  MyApp.logger.info "#{Time.now}"
  sleep 5
end

次に先ほどの /etc/logrotate.d/sample に下記のように lastaction/endscript ディレクティブを追加します。

/home/vagrant/sample.log {
    missingok
    daily
    dateext
    create 0755 vagrant vagrant
    rotate 5

    lastaction
        pid=$(cat /home/vagrant/sample_daemon.pid)
        test -d /proc/${pid} && kill -USR1 $pid
    endscript
}

これで準備完了です。
daemon_sample.rb を実行し logrotate を実行してみましょう。

$ ruby sample_daemon.rb
# 別タブで logrotate 実行
$ sudo logrotate -f /etc/logrotate.d/sample 

sample.log-20160305sample.log を見てみましょう。
ローテーション後は sample.log にログが書き出されているのがわかります。

$ cat sample.log-20160305 
I, [2016-03-05T22:01:17.052339 #18596]  INFO -- : 2016-03-05 22:01:17 +0900
I, [2016-03-05T22:01:22.054765 #18596]  INFO -- : 2016-03-05 22:01:22 +0900
I, [2016-03-05T22:01:27.055418 #18596]  INFO -- : 2016-03-05 22:01:27 +0900
$ cat sample.log
I, [2016-03-05T22:01:32.057495 #18596]  INFO -- : 2016-03-05 22:01:32 +0900
I, [2016-03-05T22:01:37.058164 #18596]  INFO -- : 2016-03-05 22:01:37 +0900
I, [2016-03-05T22:01:42.058839 #18596]  INFO -- : 2016-03-05 22:01:42 +0900

ちなみに Unicorn や Nginx はどうしているのでしょうか?
実は Unicorn も Nginx も SIGUSR1 が送られるとログファイルを reopen するように作られているのです。

おわりに

この問題に直面したとき、logrotate の挙動や open しているファイルがリネームされるとどうなるかということを知らなかったので、「数日前のログは出ているが、出ているはずの今日のログがない」という現象の原因についてまったく見当もつきませんでした。
周囲のアドバイスがなければ原因究明できなかったでしょう。
助けてくださった方々に感謝し、なんとか解決まで持っていくことができたため記録しておきます。

参考文献

お詫びと訂正

  • 「どうやってログファイルを reopen するか」の項で、存在しないファイルを reopen した場合にエラーとなるため修正しました。

ERB の partial が重かった話

業務で開発・保守している社内向け Web アプリケーションの画面の一つが重くて開けなくなりました。
エラーログからはタイムアウトにより unicorn プロセスが kill されていることがわかりました。
該当画面では3000レコードを DB から取得して一覧表示しようとしていましたが N+1 問題は解決済みで Slow Query は出ていません。
プロファイリングの結果 ERB テンプレートで使用している partial が重いということが判明しました。

サンプルコード

サンプルには Rack アプリケーションとして Sinatra を、プロファイリングには Rack::Lineprof を使用しました。

app.rb

require "sinatra"
require "rack-lineprof"

use Rack::Lineprof

get "/" do
  erb :index
end

views/index.erb

<% 2000.times do %>
  foo
  <%=erb :partial, layout: false %>
<% end %>

views/partial.erb

bar

プロファイリング結果

[Rack::Lineprof] ===============================================================

views/index.erb
 229.8ms     1 |   1  <% 2000.times do %>
   3.2ms  2000 |   2    foo
 192.8ms 10000 |   3    <%=erb :partial, layout: false %>
               |   4  <% end %>

partial で時間がかかっているのがわかります。
今回のケースですとループの中で複数の partial を使用しており、それぞれ数秒程度かかっていました。
解決方法としては、場合分けや計算等が目的であれば helper メソッドを使う、日時フォーマットの変換が目的であれば I18n を使うことが挙げられます。

YAPC::Asia 2015 に参加しました

YAPC::Asia に参加したのは2013年以来2度目で、今年の会場は東京ビッグサイト会議棟でした。

今回1番勉強になったトークは @kazeburo 氏の ISUCONの勝ち方 - YAPC::Asia Tokyo 2015 で、内容は主に ISUCON で重要となるアプリケーションや MySQL のチューニングについてでした。
ISUCON だけでなく普段の業務にも活用できる非常に有益な情報だったので、学んだことを記憶の範囲でまとめます。

ログのプロファイリング

いきなりアプリケーションのソースコードを読んで勘を頼りに・・・ではなく、まずはログをプロファイリングしてどこがボトルネックになっているか調べるのが大切だそうです。

アクセスログ

Apache アクセスログにリクエストの処理にかかった時間を出すには %D をつけます。Apache の再起動をお忘れなく。

Slow Query

すべてのクエリを Slow Query に出して解析します。

set global slow_query_log=1;
set global long_query_time=0;

元に戻すには MySQL を再起動するだけで良いので簡単とのことです。

統計ツール

ちょっと記憶に自信がないですが、トークで紹介されていた統計ツールは下記だったと思います。

プロセスが何をしているか

strace コマンドが使えるそうです。

リソース監視

top コマンド以外にも iftop (トラフィック), tcpdump, iotop (Disk IO), dstat (いろいろ) コマンドが使えるそうです。

MySQL のチューニング

MySQL のチューニングでは常にB+木をイメージするのが重要とのことです。

innoDB では Primary Key がクラスタインデックスになっており、リーフノードにデータへのポインタが格納されています。一方、セカンダリインデックスではリーフノードに PK が格納されているため、セカンダリインデックスを用いた検索では少なくとも2度検索が走ってしまいます。

また、ページングに OFFSET 句を使ってしまうと後ろのページに行くにしたがって捨てられるデータが多くなってしまいもったいないです。
解決策の1つとしては、2度のクエリに分け、まずセカンダリインデックスから id (PK) だけを、次に id を元に必要なページのレコードを取得するようにすれば、1番目のクエリが Covering Index となるので高速だそうです。

最後に

質疑応答で、私も気になっていた「アプリケーションだけや DB だけにとらわれない幅広い知識を得るにはどうしたら良いか?」という質問に対して氏が「大規模サービスの運用に携わってみること」と回答されていたのが印象的でした。
今回学んだことを業務に活用し、いつかは私も氏のように高度な技術力を持ったエンジニアになれたらと思います。

Satisfactory Mobile のソースコードを公開しました

Satisfactory Mobile というモバイル向けアンケートのソースコードGitHub で公開しました。

スクリーンショット

f:id:otoyo0122:20150822145049p:plain f:id:otoyo0122:20150822145050p:plain

デモ

https://satisfactory.mobi/

特長

UI には jQuery Mobile 1.4 を使っていて、全てではないですがなめらかな画面遷移をします。
サーバーアプリケーションは PythonDjango で、DB は MySQL を、リバースプロキシとして Nginx を使っています。
fabric で書かれたデプロイツールも入っていて、デプロイだけでなく Nginx によるメンテナンスON/OFFの切り替えも可能です。

経緯

Satisfactory Mobile は今年2月から休日を使って1ヶ月強で作ってリリースしました。
しかしその後、Google Adwords などを使ってプロモーションを実施するもユーザは増えず、サービスを世に広めることの難しさを痛感しました。
必要とされないサービスはクローズするしかありませんが、せっかく作ったのにこのまま消してしまうのはもったいないですし、ソースコードを公開すれば誰かの役に立つかもしれないと思い、今回オープンソースという形で公開することにしました。
何かのお役に立てば幸いです。

感想・Issue・PR お待ちしています!

github.com