C++ ときどき ごはん、わりとてぃーぶれいく☆

USAGI.NETWORKのなかのひとのブログ。主にC++。

NaCl tips; 標準出力でのログ採りが利く様なので

Linux NaCl stdout logging tee POSIX command C++

先日NaClでstd::coutするとホストしたウェブブラウザーのコンソールに出力が得られる事を確認しました。JavaScriptへメッセージングしてconsole.logへ出す方法も考えて居たのですが、只でさえ負荷を掛けたくないJavaScriptに大量のデバッグログをメッセージングするとか、console.logから手作業でログを回収して確認するとかイケテナイので差し当たりstd::coutでいわゆるprintfデバッグよろしくログを吐かせる事にしました。

今も昔も普通のOSはPOSIX準拠なのでteeコマンドくらいどうという事は無く使える筈なので、chromiumのログはteeで標準出力とファイルに取得すれば開発時の簡易デバッグ用に大量のログを吐かせてもさほど問題無く解析できますしコンソールでリアルタイム監視もできます。

ロガー(とりあえず仕様)

#define WRP_PRODUCT_NAME "Labyrinthian"
namespace wrp { 
#if !defined(WRP_PRODUCT_NAME)
  #define WRP_PRODUCT_NAME "UNKNOWN PRODUCT"
#endif
  class log{
    decltype(std::chrono::system_clock::now()) start;
    std::string object_name;
    void* object_address;
    static int nesting_counter;
  public:
    std::stringstream buffer;
    explicit log(std::string object_name_ = "", void* object_address_ = 0)
      : start(std::chrono::system_clock::now())
      , object_name(object_name_)
      , object_address(object_address_)
    {
      ++nesting_counter;
    }
    ~log(){
      auto end = std::chrono::system_clock::now();
      std::string indent;
      for(auto n = nesting_counter; n; --n)
        indent += "  ";
      std::cout
        << indent << "[" WRP_PRODUCT_NAME "] "
                  << object_name << " " << object_address << "\n"
        << indent << "start: "
                  << duration_cast<unit>(start.time_since_epoch()).count() << "\n"
        << indent << "end  : "
                  << duration_cast<unit>(end.time_since_epoch()).count() << "\n"
        << indent << "dt   : "
                  << duration_cast<unit>((end - start)).count() << "\n"
        ;
      std::string b;
      while(std::getline(buffer, b))
        std::cout << indent << b << "\n";
      std::cout << std::flush;
      --nesting_counter;
    }
    auto operator<<(const bool v) -> decltype(buffer<<v) { return buffer << v; }
    auto operator<<(const char* v) -> decltype(buffer<<v) { return buffer << v; }
    auto operator<<(std::string& v) -> decltype(buffer<<v) { return buffer << v; }
    auto operator<<(int& v) -> decltype(buffer<<v){ return buffer << v; }
  };
  int log::nesting_counter = -1;
}

試しに取得したログの切れっ端

[98,964327168:10:17:37.572582] Native Client module will be loaded at base address 0x00007fee00000000
[98,964048640:10:17:38.366746] NaClAbiStatHostDescStatXlateCtor: Unusual NaCl descriptor type (not constructible). The NaCl app has a file with st_mode = 010600. (This is normal for std{in,out,err}, or other inherited/injected files.)
[Labyrinthian] Labyrinthian_instance 0x10070098
start: 987.287
end  : 987.287
dt   : 0.00015
[Labyrinthian] Init 0x10070098
start: 987.287
end  : 987.287
dt   : 4e-05
attribute#0
name: id
value: nacl_targetattribute#1
name: type
value: application/x-naclattribute#2
name: src
value: Labyrinthian.nmfattribute#3
name: @dev
value: 
  [Labyrinthian] DidChangeView(const pp::Rect&, const pp::Rect&) 0x10070098
  start: 987.288
  end  : 987.288
  dt   : 0
[Labyrinthian] DidChangeView(const pp::View&) 0x10070098
start: 987.287
end  : 987.288
dt   : 0.00012
[Labyrinthian] HandleInputEvent 0x10070098
start: 1028.32
end  : 1028.32
dt   : 8e-05
type: 3
time: 41574.815489768982
おまけ: Makefileにて
  • test-server
.PHONY: test-server
test-server: all _site
	darkhttpd _site --index main.html --port 12345
  • test-client
.PHONY: test-client
test-client: 
	@ if [ -f test-client.log ]; then rm -v test-client.log; fi;
	chromium-dev "http://localhost:12345" | tee test-client.log

コンソールのログ出力が混ざると読めたもんじゃないので、`make test-server`と`make test-client`個別の端末エミュレータ−を並べてテストする感じ。

おまけのおまけ: NaClにおけるstd::chrono::system_clock

どうやら少なくともchromium-dev 20.0.1115.1でホストしたNaClでは、std::chrono::system_clock::now()してtime_since_spoch()してもウェブブラウザーのプロセスが起動してからの経過時間を取得する様だ。相対的な時間取得には困らないけど、ちょっとそれはどうなのよ、と・ｗ・；

repository