31:Te27,md`# Inspect Elixir Application *on Production Environment* *${icon({ text: 'subscribe me', collection: 'blog' })}*

Elixir 는 에러 / 장애를 바라보는 관점이 조금 다릅니다. 코드를 작성하는 과정에서 최대한 에러를 없애려는 다른 프로그래밍 언어들과는 달리, Elixir 는 에러가 발생했을 때 잘 대응하자는 철학을 가지고 있습니다. 개인적으로는 매우 멋진 접근법이라 생각하는데, Elixir 를 소개할 때에는 잘 알려지지 않는 것 같아 안타깝습니다. 저는 몇몇 장애를 겪으며 이런 접근법을 체험할 기회가 있었는데요, 그중 특별히 기억에 남았던 경험을 공유해 보려 합니다. 2019년 7월 [daybit](https://daybit.com) ${release( 'v1.9.0' )} 배포 후 [/subscription:order_books](https://docs.daybit.com/kr/#order_books) Phoenix 채널이 응답하지 않는 장애가 [incident #240](https://daybit.pagerduty.com/incidents/P3AI4SL) (이하 ${ic()}) 발생했습니다. \`OrderBooksWorker\` 프로세스의 상태를 조회하려는 프로세스들이 메시지의 응답을 받지 못해 \`timeout\` 에러가 발생하고 있는 상황이었습니다. ~~~elixir Erlang error: {:timeout, {GenServer, :call, [PgListener.OrderBooksWorker, {:list, {"BTC", "DAY", #Decimal<1E-8>}}, 5000]}} ~~~ \`timeout\` 에러는 remote shell 에서도 재현되었습니다. ~~~elixir $ ./bin/exchange_api remote_console iex(exchange_api@127.0.0.1)1> PgListener.OrderBooksWorker.list("BTC", "DAY", Decimal.new("0.0002")) Erlang error: {:timeout, {GenServer, :call, [PgListener.OrderBooksWorker, {:list, {"BTC", "DAY", #Decimal<1E-8>}}, 5000]}} ~~~ \`OrderBooksWorker\` 프로세스에 문제가 있는 것은 명확했지만, 원인을 찾기는 쉽지 않았습니다. 릴리즈한 ${release( 'v1.9.0' )} 버전에서는 \`OrderBooksWorker\` 와 관련된 변경사항은 한줄도 없었기 때문입니다. ${ic()} 은 개발환경에서 재현되지 않았기에 해결책을 찾지 못하고 시간만 흘러갔습니다. 웹 페이지가 이상하게 동작한다는 유저 피드백도 들려오기 시작하자 마음이 급해졌습니다. 결국 서버를 시작하고 30분 정도 뒤에 장애 상황이 발생한다는 점을 이용해, (극도의 안정성을 자랑한다는 Elixir) 서버를 30분 마다 재시작하는 지경에까지 이르렀습니다. 얼마후 에러가 발생할때 \`OrderBooksWorker\` 프로세스가 도대체 어떤 상태인지 궁금해 졌습니다. 당연히 먼저 떠올렸어야 할 생각이지만, 워낙 큰 배포의 여운으로 이런 생각을 떠올릴 틈이 없었습니다. ~~~elixir iex(exchange_api@127.0.0.1)1> Process.whereis(PgListener.OrderBooksWorker) |> Process.info([:message_queue_len, :memory]) [message_queue_len: 2077680, memory: 549527196] ~~~ 놀랍게도 \`OrderBooksWorker\` 프로세스의 메시지 큐에 무려 200만개의 메시지가 쌓여있었습니다. 프로세스의 메시지 큐는 대부분의 0 이거나, 빠르게 줄어들어야 합니다. 하지만 메시지 큐의 길이는 줄어들기는 커녕 계속해서 늘어나고 있었습니다. 프로세스로 전송된 메시지는 당연히 처리되지 못했고, 제때 응답을 받지 못한 송신 프로세스에서는 \`timeout\` 에러가 발생했습니다. `32:Tbe2,{ const setOpacity = value => { this.setAttributeAll( ['.cluster > rect', '.node > rect', '.node > circle', '.label', '.path'], 'opacity', value ); }; if (!this) { const diagram = mermaid`graph LR db:::natural PgListener:::natural OrderBooksWorker:::natural ChildWorkers:::natural StatsLogic:::natural TradesLogic:::natural MarketsLogic:::natural db((DB)) --"pg_notify "--> PgListener PgListener --"notification "--> OrderBooksWorker OrderBooksWorker --"put"--> ChildWorkers OrderBooksWorker --"list "--> ChildWorkers ChildWorkers --reply--> OrderBooksWorker StatsLogic --"list "--> OrderBooksWorker TradesLogic --"list "--> OrderBooksWorker MarketsLogic --"list "--> OrderBooksWorker OrderBooksWorker --"reply "--> StatsLogic subgraph "Logic Layer" StatsLogic TradesLogic MarketsLogic end `; return diagram; } setOpacity(0.2); if (hl_obw.put) { this.setAttributeAll( [ '#db > circle', '#db > .label', '#PgListener > rect', '#PgListener > .label', '#OrderBooksWorker > rect', '#OrderBooksWorker > .label', '#ChildWorkers > rect', '#ChildWorkers > .label', '.edgeLabels > g:nth-child(1) > g', '.edgePaths > g:nth-child(1) > path', '.edgeLabels > g:nth-child(2) > g', '.edgePaths > g:nth-child(2) > path', '.edgeLabels > g:nth-child(3) > g', '.edgePaths > g:nth-child(3) > path' ], 'opacity', 1 ); } else if (hl_obw.list) { this.setAttributeAll( [ '.cluster > rect', '.cluster > .label', '#StatsLogic > rect', '#StatsLogic > .label', '#TradesLogic > rect', '#TradesLogic > .label', '#MarketsLogic > rect', '#MarketsLogic > .label', '#OrderBooksWorker > rect', '#OrderBooksWorker > .label', '#ChildWorkers > rect', '#ChildWorkers > .label', '.edgeLabels > g:nth-child(4) > g', '.edgePaths > g:nth-child(4) > path', '.edgeLabels > g:nth-child(6) > g', '.edgePaths > g:nth-child(6) > path', '.edgeLabels > g:nth-child(7) > g', '.edgePaths > g:nth-child(7) > path', '.edgeLabels > g:nth-child(8) > g', '.edgePaths > g:nth-child(8) > path' ], 'opacity', 1 ); } else if (hl_obw.reply) { this.setAttributeAll( [ '.cluster > rect', '.cluster > .label', '#StatsLogic > rect', '#StatsLogic > .label', '#OrderBooksWorker > rect', '#OrderBooksWorker > .label', '#ChildWorkers > rect', '#ChildWorkers > .label', '.edgeLabels > g:nth-child(5) > g', '.edgePaths > g:nth-child(5) > path', '.edgeLabels > g:nth-child(9) > g', '.edgePaths > g:nth-child(9) > path' ], 'opacity', 1 ); } else { setOpacity(1); } return this; }33:T99f,md`\`OrderBooksWorker\` 프로세스는 DB 로 부터 받은 [notification](https://www.postgresql.org/docs/current/sql-notify.html) 메시지에 포함된 거래소의 오더북의 최신 ${highlighter( '상태를 ChildWorkers 프로세스에 저장합니다.', viewof hl_obw, 'put' )} 또한 유저 요청을 처리하는 ${highlighter( 'Logic Layer 로부터 오는 조회 메시지', viewof hl_obw, 'list' )}를 받아 ${highlighter( 'ChildWorkers 에서 찾아 반환', viewof hl_obw, 'reply' )}하는 역할도 겸하고 있습니다. \`OrderBooksWorker\` 가 메시지를 처리하지 못하는 상태가 되면, DB 에 저장된 최신상태를 반영하지 못할 뿐더러, 유저의 조회 요청도 처리할 수 없습니다. 큐가 늘어나는 원인을 찾기 위해 메시지를 처리하는 함수에 로그를 추가하려 했습니다. 하지만 서버를 시작하고 한참 후에 에러가 발생하는 것이 걱정되었습니다. 로그를 추가해 릴리즈를 만들고 배포하려면, 서버를 재시작해야 합니다. 그리고 메시지 큐의 사이즈가 늘어날때까지, 다시말해 장애가 발생할 때까지 기다려야 합니다. 장애가 발생하는 것을 기다린다니… 게다가 로그를 잘못 추가하면, 릴리즈를 다시 만들어 배포해야 합니다. 이 과정에서 유저들이 겪을 불편까지 생각해보니 로그를 추가하면서 원인을 파악하는 것은 좋지 못한 방법이라는 결론에 이르렀습니다. 그때 [visualixir 라이브러리를 해킹 하면서](https://observablehq.com/@chitacan/visualixir-on-observable-notebook) 봤던 트레이스 모듈이 떠올랐습니다. 트레이스 모듈에는 프로세스의 생성 / 종료를 추적하는 [코드](https://github.com/koudelka/visualixir/blob/40ac2c572b4822a38330f9ee5a4b43119f0d89f1/lib/visualixir/tracer.ex#L50-L51)가 구현되어 있었는데, 신기한 마음에 관련 문서를 살펴보다 프로세스간 전달되는 메시지를 추적해 표준 출력으로 확인할 수 있다는 것을 알게되었습니다. visualixir 는 \`:erlang\` 모듈에 선언된 트레이스 함수 [:erlang.trace_info](https://erlang.org/doc/man/erlang.html#trace_info-2) 사용해 프로세스간 전달되는 메시지를 추적해 SVG 로 멋지게 표현합니다. `34:Td7b,md`당장 \`:erlang.trace_info\` 사용해 메시지를 추적하고 싶었지만, \`:erlang.trace_info\` 는 추적 결과를 메시지로만 받을 수 있어 remote shell 같은 repl 환경에서는 사용하기 어려워 보였습니다. 다행히 repl 환경에서 좀 더 사용하기 편한 [:dbg](https://erlang.org/doc/man/dbg.html) 모듈을 찾을 수 있었습니다. \`:dbg\` 모듈은 프로세스를 생성하고 추적할 패턴을 전달하면, 추적 패턴이 매치될 때마다 결과를 출력합니다. \`iex\` 를 실행하고 \`:dbg\` 모듈을 테스트 해 보았습니다. 결과는 기대 이상이었습니다. 간단한 함수 호출 만으로 프로세스로 오가는 메시지들을 확인할 수 있었습니다. 과거 메시지가 제대로 왔는지 살펴보기 위해 로그를 추가하고 다시 컴파일하는 과정을 반복하던 제 모습이 정말 바보같아 보일 정도였습니다. ~~~elixir $ iex iex(1)> {:ok, pid} = Agent.start(fn -> 10 end) {:ok, #PID<0.110.0>} iex(2)> :dbg.tracer {:ok, #PID<0.119.0>} iex(3)> :dbg.p(pid, :m) # pid 프로세스로 오가는 송신, 수신 메시지를 모두 출력합니다. {:ok, [{:matched, :nonode@nohost, 1}]} iex(4)> Agent.get(pid, fn state -> state end) (<0.112.0>) << {'$gen_call',{<0.108.0>,#Ref<0.2744415596.3429629956.112413>}, {get,#Fun}} (<0.112.0>) <0.108.0> ! {#Ref<0.2744415596.3429629956.112413>,10} 10 iex(5)> :dbg.stop :ok ~~~ 프로덕션 환경에서 코드를 실행하기 앞서, 트레이스 코드가 성능에 미치는 영향을 최소화 하기 위해 추적할 프로세스를 \`OrderBooksWorker\` 로 제한하고, 필요하면 트레이스를 곧바로 종료 할 수 있도록 \`iex\` 에서 확실히 연습했습니다. 프로덕션 환경에서 추적 코드를 실행 하는 것이 올바른 방법인지 조금 고민되었지만, 로그를 추가해 다시 배포하는 것보다는 훨씬 효율적이라 판단했기 때문에 바로 실행해보기로 결정했습니다. ~~~elixir $ ./bin/exchange_api remote_console iex(exchange_api@127.0.0.1)1> pid = Process.whereis(PgListener.OrderBooksWorker) #PID<0.3537.0> iex(exchange_api@127.0.0.1)2> :dbg.tracer {:ok, #PID<0.29574.1447>} iex(exchange_api@127.0.0.1)3> :dbg.p(pid, :m) {:ok, [{:matched, :"exchange_api@127.0.0.1", 1}]} (<0.3537.0>) << {notification,<0.3538.0>,#Ref<0.1229483035.860880898.9737>, <<"order_book_change">>, <<"{\"table\" : \"order_books\", \"type\" : \"INSERT\", \"data\" :{\"quote\":\"KRW\",\"base\":\"ETH\",\"intvl\":10.00000000,\"min_price\":154930.00000000,\"max_price\":154940.00000000,\"sell_vol\":3.63600000,\"buy_vol\":0.00000000,\"sell_orders\":1,\"buy_orders\":0}}">>} (<0.3537.0>) << {notification,<0.3538.0>,#Ref<0.1229483035.860880898.9737>, <<"order_book_change">>, <<"{\"table\" : \"order_books\", \"type\" : \"UPDATE\", \"data\" :{\"quote\":\"KRW\",\"base\":\"ETH\",\"intvl\":100.00000000,\"min_price\":154900.00000000,\"max_price\":155000.00000000,\"sell_vol\":17.05400000,\"buy_vol\":0.00000000,\"sell_orders\":2,\"buy_orders\":0}}">>} ~~~ 추적 코드를 실행하자마자 바로 이상함을 느낄 수 있었습니다. \`OrderBooksWorker\` 의 상태를 조회하거나 업데이트하는 메시지가 거의 보이지 않았기 때문입니다. 상세한 분석을 위해 [추적된 메시지 일부를 따로 저장하고](#trace_log), 분석해 보았습니다.`35:T733,{ const setOpacity = value => { this.setAttributeAll(['.node > rect', '.label', '.path'], 'opacity', value); }; if (!this) { const procs = _.chain(messages) .uniqBy(({ from, to }) => `${from}-${to}`) .map( ({ from, to, body: [message] }) => `${parsePid(from)} -. ${message} .-> ${parsePid(to)}` ) .value() .join('\n'); return mermaid`graph TB ${procs} `; } setOpacity(0.2); if (hl_msg.notification) { this.setAttributeAll( [ '#OrderBooksWorker > rect', '#OrderBooksWorker > .label', '#PgListener > rect', '#PgListener > .label', '.edgeLabels > g:nth-child(1) > g', '.edgePaths > g:nth-child(1) > path' ], 'opacity', 1 ); } else if (hl_msg['$gen_cast']) { this.setAttributeAll( [ '#OrderBooksWorker > rect', '#OrderBooksWorker > .label', '#ChildWorker > rect', '#ChildWorker > .label', '.edgeLabels > g:nth-child(6) > g', '.edgePaths > g:nth-child(6) > path' ], 'opacity', 1 ); } else if (hl_msg.io_request) { this.setAttributeAll( [ '#OrderBooksWorker > rect', '#OrderBooksWorker > .label', '#standard_error > rect', '#standard_error > .label', '.edgeLabels > g:nth-child(2) > g', '.edgePaths > g:nth-child(2) > path' ], 'opacity', 1 ); } else if (hl_msg.io_reply) { this.setAttributeAll( [ '#OrderBooksWorker > rect', '#OrderBooksWorker > .label', '#standard_error > rect', '#standard_error > .label', '.edgeLabels > g:nth-child(3) > g', '.edgePaths > g:nth-child(3) > path' ], 'opacity', 1 ); } else { setOpacity(1); } return this; }36:T639,md`\`OrderBooksWorker\` 는 DB 로부터 전달받은 ${highlighter( 'notification', viewof hl_msg )}, \`ChildWorker\` 에 상태를 저장하는 ${highlighter( '$gen_cast', viewof hl_msg )}, 보다 \`standard_error\` 프로세스와 주고 받는 ${highlighter( 'io_request', viewof hl_msg )}, ${highlighter( 'io_reply', viewof hl_msg )} 메시지를 5배나 더 많이 처리하고 있었습니다. 추적된 ${highlighter( 'io_request', viewof hl_msg )} 메시지는 decimal 라이브러리에서 생성된 경고 문구를 담고 있었습니다. ~~~erlang {put_chars,unicode, <<"warning: passing float to Decimal.new/1 is deprecated as floats have inherent inaccuracy. Use Decimal.from_float/1 or Decimal.cast/1 instead\n (decimal) lib/decimal.ex:1241: Decimal.new/1\n (ecto) lib/ecto/type.ex:587: Ecto.Type.cast/2\n (ecto) lib/ecto/changeset.ex:509: Ecto.Changeset.cast_field/8\n ...\n">>}} ~~~ 순간 저 경고 메시지가 이 모든 사태의 원인일지도 모른다는 생각이 들었습니다. 출력하려는 텍스트의 길이도 길이지만, 잠깐동안의 추적에도 ${highlighter( '꽤 많은 요청이', viewof hl_msg, 'io_request' )} 발생하는 것이 프로세스의 성능에 영향을 줄 수 있어 보였기 때문입니다. 하지만 한편으론 단순 경고 출력이 시스템의 핵심 프로세스를 멈추게 할 수 있다는게 상식적으로 이해가 되지 않았습니다. \`IO.warn\` 의 소스코드를 살펴보고 나서야 \`OrderBooksWorker\` 에서 발생한 상황이 이해되기 시작했습니다.`37:T12e2,md`배포 후 몇일동안 저를 괴롭혔던 ${ic()} 은 decimal 라이브러리의 \`IO.warn\` 을 제거하자 해결되었습니다. ${ic()} 의 원인을 파악하는 과정은 아주 독특한 경험이었습니다. 파악조차 쉽지 않은 오류를 찾느라 로그를 추가하고 배포를 반복하는 과정은 없었습니다. 시스템을 중단하지 않고도 비즈니스 로직을 처리하는 프로세스들 상태를 조회하고, 함수와 메시지들을 추적해 원인을 파악해 내었습니다. 언어나 프레임워크에서 지원하는 다양한 디버깅 도구를 사용해 시스템의 동작을 파악하고 문제를 해결하는 것을 즐기는 저에게 배포 후에도 이정도 수준의 도구들을 사용할 수 있는 것에 너무나도 기뻤습니다. 하지만 한편으론 프로덕션 환경에서 \`:dbg\` 를 사용해 장애를 진단하고, 해결하는 것이 올바른 방법인지 고민이 되었습니다. \`:dbg\` 는 프로덕션 환경에서 곧바로 사용할 수 있었지만, 보통 이런 디버깅 도구들은 개발환경에서만 허용되는 것이 일반적이기 때문입니다. 저는 트레이스를 좀 더 살펴보기로 했습니다. 트레이스 모듈, 함수들의 사용방법 보다, Erlang 에서는 왜 트레이스를 사용하게 되었고, 왜 프로덕션 릴리즈에서도 사용할 수 있는지 알고 싶었습니다. 그 이후 내내 궁금증을 해결해 줄 수 있을만한 컨텐츠를 찾아다녔습니다. 새로운 사실을 알게 될 때마다 작성중이던 포스트의 구조가 바뀌었습니다. 하지만 궁금증은 전혀 해결되지 않았습니다. 답답했던 상황은 Erlang Solution 의 블로그 포스트 [The Best Code BEAM SF talks from the 2010s](https://www.erlang-solutions.com/blog/the-best-code-beam-sf-talks-from-the-2010s.html) 에서 [Operable Erlang & Elixir](https://www.youtube.com/watch?v=OR2Gc6_Le2U) 를 다시 만나게 되면서, 완전히 바뀌었습니다. 트레이스에 아무런 관심이 없을 때에는 전혀 이해하지 못했던 영상에 제가 몇달동안 찾아 헤매던 궁금증에 대한 해답이 들어있었습니다. Elixir 의 Functional programming 코딩 스타일과 와 Process 모델은 효율적인 코드를 작성하고, 견고한 시스템을 설계하는데 많은 도움을 줍니다. 하지만 ${ic()} 처럼 프로덕션 환경에서는 이런 장치들을 뛰어넘어 예상치 못한 곳에서 발생한 장애가 시스템을 망쳐버릴 수 있습니다. 이때가 바로 Elixir 의 진가가 발휘되는 순간입니다. Elixir 의 모든 코드는 프로세스 단위로 실행됩니다. 각각의 프로세스는 자신만의 상태를 가지며, 메시지를 주고 받습니다. 프로세스는 완전히 격리된 실행 단위이기 때문에, 코드의 오류는 프로세스의 경계를 넘지 못합니다. 덕분에 Elixir 시스템은 한번의 잘못된 오류로 완전히 멈추지 않습니다. 그 사이 개발자들은 remote shell 에 접속해 시스템과 직접 상호작용하며 문제를 파악하고, 해결할 수 있습니다. \`Process\` 모듈을 사용해 문제가 발생한 프로세스를 찾고, 프로세스의 상태를 확인합니다. 트레이스를 사용하면 시스템의 모든 곳에서 호출되는 함수와 메시지를 추적할 수 있습니다. 노드, 프로세스의 상태를 좀 더 자세히 살펴보고 싶다면 Observer 를 실행할 수도 있습니다. 문제를 복구하기 위해, 시스템을 재배포하거나 재시작하지 않아도 됩니다. remote shell 에서 모듈을 새롭게 정의하거나 컴파일된 모듈을 전달해 문제를 즉시 해결할 수 있습니다. (꽤 어렵긴 하지만) 시스템을 멈추지 않고 코드를 다시 배포하는 것도 가능합니다. 배포를 위한 바이너리가 만들어지면 로그 출력이나 시스템의 상태만으로 상황을 파악하는데 익숙해진 우리들에게 Elixir 의 도구들이 허용하는 개입의 정도는 아주 위험해 보이기도 합니다. 하지만 장애가 발생했을때 로그나 스택 트레이스만으로 문제를 파악하지 못해 골머리를 앓았던 경험이 있는 개발자 분들이라면, **에러를 잘 다룰수 있도록 도와주는 Elixir 의 운영적인 특징과 철학**이 분명 흥미로워 보이리라 생각합니다. 한국의 커뮤니티에 Elixir 가 소개될 때 언어적인 특징, 프로세스 모델 뿐만 아니라 운영적인 특징과 철학도 함께 소개되었으면 좋겠습니다.`38:T643,parser = log => { const CAST = ') << {'; const CALL = ' ! {'; const parsePid = d => { const fmt = /<(.*)>/g.exec(d); return fmt === null ? d : fmt[0]; }; const resolveFrom = (d, i, arr) => { if (d.type === 'call') { return d; } if (d.body[0] === 'code_server') { return { ...d, from: 'code_server' }; } const from = arr .filter(e => e.type === 'call') .find(e => d.body[1] === e.body[2]); return from ? { ...d, from: from.to } : { ...d, from: d.body[1] }; }; const parse = line => { if (line.includes(CALL)) { const [header, _body] = line.split(CALL); const [from, to] = header.split(' ').map(parsePid); const body = _body .split(',') .slice(0, 3) .map(d => d.replace(/'/g, '')); return { raw: line, type: 'call', from, to, body }; } else if (line.includes(CAST)) { const [header, _body] = line.split(CAST); const to = parsePid(header); const body = _body.split(',').slice(0, 3); return { raw: line, type: 'cast', to, body }; } else { return { raw: line }; } }; const lines = _.chain(log.split('\n')) .reduce((acc, c) => { if (c.startsWith('(')) { return [...acc, [c]]; } else { const [last, ...rest] = acc.reverse(); return [[...last, c.replace(/^\s+/, '')], ...rest].reverse(); } }, []) .map(d => d.join('')) .value(); return lines .map(parse) .map(resolveFrom) .map(d => { return { ...d, to: processName(d.to), from: processName(d.from) }; }); }39:[{"id":"e28fe2d15cd1cd76124dbb0062fcc3e5429f742dcfed5e8ed8c44c7ff2184dd0158b5ce1b4d56f26c8cd2001c3c1d36f4591118135130dc128efb60f9c98163a","href":"https://static.observableusercontent.com/files/e28fe2d15cd1cd76124dbb0062fcc3e5429f742dcfed5e8ed8c44c7ff2184dd0158b5ce1b4d56f26c8cd2001c3c1d36f4591118135130dc128efb60f9c98163a","name":"trace_log@1","type":"application/octet-stream","lastModified":1584603038785.815,"size":44470},{"id":"569ec92492d20686677f11a148d2d06d35ae7a19f03a07443a8fbb1b327f636c0b64937da1e929e898567c234d114e79e153ab4a34d34f8effb0902338c83806","href":"https://static.observableusercontent.com/files/569ec92492d20686677f11a148d2d06d35ae7a19f03a07443a8fbb1b327f636c0b64937da1e929e898567c234d114e79e153ab4a34d34f8effb0902338c83806","name":"logger.svg","type":"image/svg+xml","lastModified":1584815268087.623,"size":20878}] 2f:{"title":"Inspect Elixir Application","cells":[{"id":0,"value":"$31","pinned":false,"hidden":false,"mode":"ojs"},{"id":687,"value":"$32","pinned":false,"hidden":false,"mode":"ojs"},{"id":197,"value":"$33","pinned":false,"hidden":false,"mode":"ojs"},{"id":17,"value":"$34","pinned":false,"hidden":false,"mode":"ojs"},{"id":168,"value":"messages = parser(trace_log)","pinned":false,"hidden":false,"mode":"ojs"},{"id":178,"value":"{\n let message = '';\n let color = '#c1e4f7';\n\n if (hl_msg.io_request) {\n message = 'io_request';\n color = '#ffbbb1';\n } else if (hl_msg.io_reply) {\n message = 'io_reply';\n color = '#ffbbb1';\n } else if (hl_msg['$gen_cast']) {\n message = '$gen_cast';\n color = '#c7e8ac';\n } else if (hl_msg.notification) {\n message = 'notification';\n color = '#c7e8ac';\n }\n\n return vl({\n width: 300,\n data: {\n values: messages.map(d => ({ message: d.body[0] }))\n },\n mark: 'bar',\n encoding: {\n x: { field: 'message', type: 'nominal' },\n y: { aggregate: 'count', field: 'b', type: 'quantitative' },\n color: {\n condition: {\n test: `datum.message === '${message}'`,\n value: color\n },\n value: '#c1e4f7'\n }\n }\n });\n}","pinned":false,"hidden":false,"mode":"ojs"},{"id":821,"value":"$35","pinned":false,"hidden":false,"mode":"ojs"},{"id":1145,"value":"{\n if (\n !hl_msg.notification &&\n !hl_msg['$gen_cast'] &&\n !hl_msg.io_request &&\n !hl_msg.io_reply\n ) {\n return this;\n }\n return messages.find(({ body: [d] }) => {\n if (hl_msg.notification) {\n return d === 'notification';\n } else if (hl_msg['$gen_cast']) {\n return d === '$gen_cast';\n } else if (hl_msg.io_request) {\n return d === 'io_request';\n } else if (hl_msg.io_reply) {\n return d === 'io_reply';\n }\n });\n}","pinned":false,"hidden":false,"mode":"ojs"},{"id":983,"value":"$36","pinned":false,"hidden":false,"mode":"ojs"},{"id":850,"value":"md`\\`IO.warn\\` 함수는 메시지를 [동기 방식으로](https://github.com/erlang/otp/blob/f9cbc2a6f6c03b529860857f94242ea80b30d3f3/lib/stdlib/src/io.erl#L569-L588) \\`standard_error\\` 메시지를 프로세스에 전달합니다. 비동기 메시지 전달이 일상인 Elixir 에서 동기 방식이란 메시지를 보내고(${highlighter(\n 'io_request',\n viewof hl_msg\n)}) 응답이(${highlighter(\n 'io_reply',\n viewof hl_msg\n)}) 올때까지 기다리는 방식입니다. 응답을 기다리는 중에 다른 메시지가 도착하면, 메시지 큐에 저장하고 응답을 받은 이후에 처리합니다. \\`IO.warn\\` 은 매우 빠르게 동작하기 때문에 일반적인 상황에서는 별 문제가 없습니다. 하지만 \\`OrderBooksWorker\\` 처럼 아주 많이 \\`IO.warn\\` 을 호출하면 이야기가 달라집니다. \\`IO.warn\\` 을 처리하는데 걸리는 시간은 동일하지만, 호출하는 횟수가 늘어나면서 메시지가 큐에 쌓일 확률이 높아집니다. 비동기 메시지를 전달하면 메시지 큐에 쌓이고 말겠지만, 동기 방식은 문제가 발생할 수 있습니다. 큐에 쌓인 메시지들을 처리하기 전에는 요청한 메시지에 대한 응답을 줄 수 없기 때문입니다. 동기 방식을 호출하는 프로세스에서는 응답을 무작정 기다릴 수 없기 때문에 설정된 시간이 지나면 \\`timeout\\` 에러가 발생합니다. 결국 \\`OrderBooksWorker\\` 는 **경고 문구를 출력하느라 다른 메시지를 처리하지 못하고 큐에 쌓고 있었던 것입니다.**`","pinned":false,"hidden":false,"mode":"ojs"},{"id":856,"value":"md`${highlighter('Logger.warn', viewof hl_warn, 'logger')} 은 ${highlighter(\n 'IO.warn',\n viewof hl_warn,\n 'io'\n)} 과는 다르게 비동기로 동작하고, 메시지 큐를 Logger 프로세스에서 유지하기 때문에 Logger.warn 호출 때문에 어플리케션의 동작에 영향을 주는 것을 피할 수 있습니다. 하지만 decimal 라이브러리는 컴파일 타임에 확실한 경고를 줄 수 있는 IO.warn 을 선택한 것으로 보입니다.`","pinned":false,"hidden":false,"mode":"ojs"},{"id":912,"value":"{\n if (!this) {\n const svg = await FileAttachment(\"logger.svg\").text();\n const root = html`

${svg}

`;\n root.setAttributeAll = function(selectors, attr, value) {\n this.querySelectorAll(selectors.join(',')).forEach(d =>\n d.setAttribute(attr, value)\n );\n };\n return root;\n }\n this.setAttributeAll(['svg > g > *'], 'opacity', 0.1);\n if (hl_warn.logger) {\n const selectors = [6, 7, 8, 9, 14, 16, 24].map(\n d => `svg > g *:nth-child(${d})`\n );\n this.setAttributeAll(selectors, 'opacity', 1);\n } else if (hl_warn.io) {\n const selectors = [2, 3, 29, 30, 31, 32, 33, 34, 36, 38, 10, 11].map(\n d => `svg > g > *:nth-child(${d})`\n );\n this.setAttributeAll(selectors, 'opacity', 1);\n } else {\n this.setAttributeAll(['*'], 'opacity', 1);\n }\n return this;\n}","pinned":false,"hidden":false,"mode":"ojs"},{"id":862,"value":"$37","pinned":false,"hidden":false,"mode":"ojs"},{"id":7,"value":"md`---\n\n## Appendix`","pinned":false,"hidden":false,"mode":"ojs"},{"id":1001,"value":"viewof hl_msg = new View({})","pinned":false,"hidden":false,"mode":"ojs"},{"id":1053,"value":"viewof hl_obw = new View({})","pinned":false,"hidden":false,"mode":"ojs"},{"id":1251,"value":"viewof hl_warn = new View({})","pinned":false,"hidden":false,"mode":"ojs"},{"id":998,"value":"highlighter = (text, view, key = text) => {\n const el = text.startsWith('<')\n ? html`${text}`\n : html`${text}`;\n el.addEventListener('mouseover', () => {\n view.value = { ...view.value, [key]: true };\n });\n el.addEventListener('mouseout', () => {\n view.value = { ...view.value, [key]: false };\n });\n return el;\n}","pinned":false,"hidden":false,"mode":"ojs"},{"id":756,"value":"processName = pid => {\n switch (pid) {\n case '<0.809.0>':\n return 'PgListener';\n case '<0.808.0>':\n return 'OrderBooksWorker';\n case '<0.66.0>':\n return 'standard_error';\n case '<0.2139.0>':\n case '<0.2143.0>':\n case '<0.2145.0>':\n case '<0.2147.0>':\n case '<0.2149.0>':\n return 'ChildWorker';\n default:\n return pid;\n }\n}","pinned":false,"hidden":false,"mode":"ojs"},{"id":754,"value":"$38","pinned":false,"hidden":false,"mode":"ojs"},{"id":374,"value":"ic = () => incident('#240', 'https://www.pagerduty.com')","pinned":false,"hidden":false,"mode":"ojs"},{"id":772,"value":"parsePid = d => {\n const fmt = /<(.*)>/g.exec(d);\n return fmt === null ? d : fmt[1];\n}","pinned":false,"hidden":false,"mode":"ojs"},{"id":774,"value":"link = (from, to, message, a = '-.', b = '.-') =>\n `${parsePid(from)}[${from}] ${a}${message}${b}> ${parsePid(to)}[${to}]`","pinned":false,"hidden":false,"mode":"ojs"},{"id":25,"value":"function mermaid(...args) {\n const div = document.createElement('div');\n div.style.width = `${width}px`;\n div.style['overflow-x'] = 'scroll';\n div.innerHTML = mermaidAPI.render(\n `mermaid-render-element-${guid()}`,\n String.raw(...args)\n );\n div.querySelector('svg').style.width = '100%';\n div.setAttributeAll = function(selectors, attr, value) {\n this.querySelectorAll(selectors.join(',')).forEach(d =>\n d.setAttribute(attr, value)\n );\n };\n return div;\n}","pinned":false,"hidden":false,"mode":"ojs"},{"id":28,"value":"function guid() {\n\treturn 'xxxxxxxx-xxxx-4xxx-yxxx-xxxxxxxxxxxx'.replace(/[xy]/g, function(c) {\n\t\tvar r = Math.random()*16|0, v = c == 'x' ? r : (r&0x3|0x8);\n\t\treturn v.toString(16);\n\t});\n}","pinned":false,"hidden":false,"mode":"ojs"},{"id":606,"value":"html``","pinned":false,"hidden":false,"mode":"ojs"},{"id":523,"value":"trace_log = await FileAttachment(\"trace_log@1\").text()","pinned":false,"hidden":false,"mode":"ojs"},{"id":977,"value":"md`---`","pinned":false,"hidden":false,"mode":"ojs"},{"id":21,"value":"mermaidAPI = {\n const pkg = await require('mermaid@8.4.4/dist/mermaid.min.js');\n const mermaidAPI = pkg.mermaidAPI;\n mermaidAPI.initialize({\n fontFamily: 'monospace'\n });\n return mermaidAPI;\n}","pinned":false,"hidden":false,"mode":"ojs"},{"id":370,"value":"import {incident, release} from '@chitacan/labels'","pinned":false,"hidden":false,"mode":"ojs"},{"id":413,"value":"import {slider} from '@jashkenas/inputs'","pinned":false,"hidden":false,"mode":"ojs"},{"id":747,"value":"import { Scrubber } from \"@mbostock/scrubber\"","pinned":false,"hidden":false,"mode":"ojs"},{"id":14,"value":"_ = require('lodash')","pinned":false,"hidden":false,"mode":"ojs"},{"id":967,"value":"import { View } from '@mbostock/synchronized-views'","pinned":false,"hidden":false,"mode":"ojs"},{"id":1354,"value":"import { icon } from '@chitacan/rss'","pinned":false,"hidden":false,"mode":"ojs"},{"id":175,"value":"vl = require(\"vega-embed@4\")","pinned":false,"hidden":false,"mode":"ojs"}],"files":"$W39","stdlib":"1","titling":"auto"}