Archive for 2012/08/16

CeLogFlush.exe と Kernel Tracker

WEC 7 や WinCE 6.0 のデバイスドライバや、アプリケーションの開発を行っていて、期待しているパフォーマンスが達成されなかったり、予想していたタイミングでスレッドが実行されない、などの問題が生じた場合、どこに要因があるのかを調べるには、カーネルのログ機能と Kernel Tracker を使うのが便利です。WEC/WinCE カーネルのログ機能は、デバッグメッセージを出力するなどの単純なものではなく、スレッドの切り替わりや、各種同期オブジェクトの獲得や解放、および、割り込み処理の発火など、OS 内部の詳細な動きを記録できるようになっています。

WEC/WinCE カーネルが出力したログの内容は、Kernel Tracker を使って、グラフィカルに表示できます。以下に、WEC 7 をデバイスエミュレータで動かして取得したログの内容を、Kernel Tracker で表示した様子を示します。

Kernel Tracker の画面キャプチャ

Kernel Tracker の画面キャプチャ

上の画面キャプチャを見ると、標準シェル(explorer.exe)のスレッドが 100ms の Quantum を使い果たし、servicesd.exe 内の同じ優先度を持つスレッドに切り替わった様子が分かります。また、ほぼ一定間隔で割り込み応答動作が起きていることも分かります。これは、1ms おきに発生するタイマ割り込みに対するものです。

このように、WEC/WinCE カーネルのログ機能を使うと、1ms より細かい時間精度でスレッドの動きを知ることができ、OS 内部の動作を分析するのに役立ちます。カーネルデバッガを使ってステップ実行する場合とは異なり、通常の動作での OS 内部の振る舞いを知ることができますので、うまく使えば、強力なツールとなります。また、後述するように、出荷後のデバイスに搭載されているものなど、ログ機能を有効にしない OS イメージに対しても、一時的にログ機能を有効にしてログ採取できるのも、非常に便利な点でしょう。

■CeLogFlush.exe によるログ採取(標準設定)
WEC/WinCE カーネルのログ機能については、リファレンスの次のページで説明されています:

 CeLog Event Tracking (Windows Embedded Compact 7)
 http://msdn.microsoft.com/en-us/library/ee479601

 CeLog Event Tracking Overview (Windows Embedded CE 6.0)
 http://msdn.microsoft.com/en-us/library/ee480432(v=winembedded.60)

このログ機能を使って、WEC/WinCE カーネルが出力するログをファイルに保存する手順は、次の通りです。以下の説明は WEC 7 の場合ですが、WinCE 6.0 でも同様です。

  1. OS Design のカタログ項目で、Target Control Support (Shell.exe) を選択する(SYSGEN_SHELL を有効にする)。
  2. OS Design の「構成プロパティ」の Build Options で、Enable KITL を Yes に設定する。
  3. 同じく Build Options で、Flush tracked events to release directory を Yes (IMGAUTOFLUSH=1) に設定する。

ただし、WinCE 6.0 の場合は、次のいずれかの手順が追加で必要です。

  • OS Design の「構成プロパティ」の Build Options で、Enable event tracking during boot を Yes (IMGCELOGENABLE=1) に設定する。
  • project.bib の FILES セクションに、celog.dll を追加する。

つまり、WinCE 6.0 の場合は、IMGAUTOFLUSH に加えて IMGCELOGENABLE も1に設定しなければ(または、明示的に celog.dll を .bib ファイルに記述しなければ)、カーネルのログ出力が起きません。一方、WEC 7 の方は、IMGCELOGENABLE は設定しなくても、IMGAUTOFLUSH を1に設定すればカーネルのログ出力が起きるのです。実際、リファレンスを見ても、そのように説明されています:

 Including CeLogFlush in a Run-Time Image (Windows Embedded CE 6.0)
 http://msdn.microsoft.com/en-us/library/ee481413(v=WinEmbedded.60).aspx

 Enable CeLog Event Tracking (Windows Embedded Compact 7)
 http://msdn.microsoft.com/en-us/library/ee480716

WinCE 6.0 と WEC 7 の、この違いは、%_WINCEROOT%/public/COMMON/oak/files/common.bib の記述内容の違いによるものです。WinCE 6.0 の common.bib には、IMGCELOGENABLE が1の場合に celog.dll を MODULES セクションに追加する行があるだけです。一方、WEC 7 の common.bib では、次のようになっています。

MODULES
;  Name            Path                                           Memory Type
;  --------------  ---------------------------------------------  -----------
…
IF IMGCELOGENABLE
   celog.dll       $(_FLATRELEASEDIR)\celog.dll                NK  SHK
ENDIF IMGCELOGENABLE
…

; ====================================================================
; FILES section
;
; ====================================================================

FILES
…
; Setting IMGAUTOFLUSH or IMGOSCAPTURE without IMGCELOGENABLE will include
; celog.dll in the FILES section instead of MODULES, so that the DLL will
; be loaded late enough to read settings from the device registry.
IF IMGCELOGENABLE !
IF IMGAUTOFLUSH
   celog.dll       $(_FLATRELEASEDIR)\celog.dll                NK  SH
ENDIF IMGAUTOFLUSH
IF IMGOSCAPTURE
   celog.dll       $(_FLATRELEASEDIR)\celog.dll                NK  SH
ENDIF IMGOSCAPTURE
ENDIF IMGCELOGENABLE


WEC 7 の場合は、common.bib の内容が上のようになっているため、IMGCELOGENABLE を設定せずに IMGAUTOFLUSH だけを1に設定した場合は、celog.dll が .bib ファイルの FILES セクションに追加されますので、OS イメージに celog.dll が収録されます。これに対して、WinCE 6.0 では、IMGCELOGENABLE が1に設定されなければ celog.dll が OS イメージに収録されません。そのため、IMGCELOGENABLE も1に設定するか、または、project.bib の FILES セクションに celog.dll の行を追加する必要があるのです。

上記の設定を行った OS Design をビルドして、ターゲットデバイスにダウンロードして動かすと、Flat Release Drectory、つまり環境変数 _FLATRELEASEDIR が指すディレクトリに celog.clg というファイルが作られて、カーネルが出力したログが書き込まれます。ターゲットデバイスと Platform Builder との接続を切れば、celog.clg ファイルを開くことができるようになりますので、Kernel Tracker で開いてみて下さい。

WEC 7 の場合は、.clg ファイルが Kernel Tracker と関連づけられているため、.clg ファイルのアイコンをダブルクリックすると、Kernel Tracker が起動します。WinCE 6.0 の場合は、Kernel Tracker を起動した後、File メニューで .clg ファイルを開く必要があります。詳細は、次のページをご覧下さい:

 Remote Timeline Viewer (Windows Embedded Compact 7)
 http://msdn.microsoft.com/en-us/library/gg156030

 Starting Kernel Tracker in File Mode (Windows Embedded CE 6.0)
 http://msdn.microsoft.com/en-US/library/ee480674(v=winembedded.60)

■CeLogFlush.exe によるログ採取(設定のカスタマイズ)
さて、KITL と Target Control Support (Shell.exe) を有効にした OS イメージで、Flat Release Directory に WEC/WinCE カーネルのログを出力できることは分かりました(Target Control Support (Shell.exe) ではなく、Release Directory File System を有効にするのでも構いません)。これらを有効にしない限り、カーネルのログをファイルへ出力することは、できないのでしょうか?

Flat Release Directory 以外のディレクトリへファイルを出力することは、レジストリ設定により可能です。WEC/WinCE カーネルのログは、celog.dll によって RAM 上のリングバッファへ格納され、その内容を、CeLogFlush.exe がファイルへ出力する、という仕組みになっています。CeLogFlush.exe および celog.dll に対するレジストリ設定は、リファレンスの次のページで説明されています。

 CeLog Registry Settings (Windows Embedded Compact 7)
 http://msdn.microsoft.com/en-us/library/ee480468

 CeLogFlush Registry Settings (Windows Embedded CE 6.0)
 http://msdn.microsoft.com/en-US/library/ee481192(v=winembedded.60)

ログを出力するファイルは、上のページの説明にある通り、[HKEY_LOCAL_MACHINE\System\CeLog] キーの FileName で設定できます。たとえば、SD カードにログファイルを出力する場合は、次のような行を .reg ファイルへ追加すればよいでしょう。

[HKEY_LOCAL_MACHINE\System\CeLog]
    "BufferSize"=dword:20000
    "FileName"="\\Storage Card\\celog.clg"
    "FileSize"=dword:0
    "FileFlags"=dword:0
    "FlushTimeout"=dword:2710
    "ThreadPriority"=dword:F8
    "Transport"="LocalFile"
    "UseUI"=dword:0
    "ZoneCE"=dword:c003e2


なお、BufferSize や FlushTimeout の値は、デフォルトよりも小さくしないで下さい。これらを小さくすると、celog.dll が確保するリングバッファがすぐに満杯になったり、あるいは、ログが出力されていなくてもすぐにバッファのフラッシュ時間に達してしまい、必要以上にログ出力が増えます(CeLogFlush.exe によるファイルへのログ書き込みによっても、カーネルのログ出力が発生することに留意して下さい)。その結果、OS の実効速度が実用にならないものになってしまう場合もあるからです。

もう一点注意です。[HKEY_LOCAL_MACHINE\System\CeLog] キーの FileName 値の設定で、ログの出力先を外部ストレージにする場合、そのストレージデバイスがマウントされるよりも前に CeLogFlush.exe が起動されないようにしなければいけません。IMGAUTOFLUSH を1に設定した場合、common.reg ファイルの記述により、[HKEY_LOCAL_MACHINE\init] キーに対する以下の設定が追加されます:

[HKEY_LOCAL_MACHINE\init]
        "Launch05"="CeLogFlush.exe"


この設定では、デバイスマネージャ(device.dll)よりも先に CeLogFlush.exe がロード・起動されてしまうため、CeLogFlush.exe が初期化時に出力ファイルを作成できず、エラーで終了してしまいます。従って、device.dll の起動順序(Launch20)よりも後の起動順序を設定する必要があります。デバイスマネージャが起動してストレージがマウントされるまでに若干の時間がかかることを考慮すると、gwes.dll(Launch30)の後にする方が、より確実だと思われます。

■ログ機能を有効にしていない OS イメージでのログ採取
ここまでの説明で、celog.dll と CeLogFlush.exe を OS イメージに組み込んでいれば、WEC/WinCE カーネルのログをファイルへ出力できることが分かりました。しかし、カーネルのログが常にファイルへ出力されると、若干のオーバーヘッドを生みますし、また、セキュリティの観点からも、好ましいことでは、ありません。このことは、上で紹介した WEC 7 のリファレンスページにも注意書き(Note)として記載されています。

さて、今回のエントリの冒頭で、次のように書きました:

また、後述するように、出荷後のデバイスに搭載されているものなど、ログ機能を有効にしない OS イメージに対しても、一時的にログ機能を有効にしてログ採取できるのも、非常に便利な点でしょう。

実は、celog.dll と CeLogFlush.exe を OS イメージに組み込んでいなくても、OS の起動後に celog.dll をカーネルにロードさせて、ログ機能を有効にできるのです。従って、USB メモリなどの外部ストレージに celog.dll と CeLogFlush.exe を入れておき、OS の起動後に、手動で CeLogFlush.exe を始動すれば、必要な時にだけログを採取できます。このことは、リファレンスの次のページでも説明されています:

 Collecting Data On A Standalone Device With CeLogFlush (Windows Embedded CE 6.0)
 http://msdn.microsoft.com/en-US/library/ee480886(v=winembedded.60)

CeLogFlush.exe は、起動すると終了要求されるまで、celog.dll が出力したログをリングバッファから読み出してファイルへ出力するループ動作を実行します。”SYSTEM/CeLogFlush Quit” という名前の event に対して SetEvent() を呼び出すことにより、CeLogFlush.exe に終了要求できます。または、CeLogFlush.exe のソースファイルと同じ場所に収録されている、CeLogStopFlush というサンプルプログラムも参考になります。CeLogStopFlush は、CeLogFlushCommon.lib というライブラリを CeLogFlush.exe と共用しており、CeLogFlushCommon.lib の FLUSH_SignalStopFlush() という関数を呼び出します。FLUSH_SignalStopFlush() は、”SYSTEM/CeLogFlush Quit” という名前の event を OpenEvent() でオープンして、SetEvent() を呼び出すだけです(※SetEvent() の後、CloseHandle() を呼び出します)。

■おまけ
いかがでしょうか?ここまでの説明で、WEC/WinCE カーネルのログ機能が、出荷用の OS イメージに対する障害解析ツールとしても利用可能な、強力なものであることを、お分かり頂けたのではないかと思います。以下に、このログ機能について、いくつか補足します。

(1)CeLogFlush.exe と celog.dll のソースコード
 CeLogFlush.exe と celog.dll のソースコードは、それぞれ次の場所にあります:

 CeLogFlush.exe
 %_WINCEROOT%/public/COMMON/sdk/samples/celog/flush/CeLogFlush/

 celog.dll
 %_WINCEROOT%/private/winceos/COREOS/nk/celog/celogdll/

 CeLogFlush.exe と celog.dll は、”SYSTEM/CeLog Data” という名前の共有メモリ領域(CreateFileMapping() によって生成されるメモリマップドオブジェクト)上に配置したリングバッファを介して、WEC/WinCE カーネルが出力したログデータを受け渡しします。リングバッファが満杯に近付くと、celog.dll が event オブジェクトを使って CeLogFlush.exe に通知して、リングバッファの内容をファイルへ出力させる、という連携です。リングバッファのサイズは、celog.dll が共有メモリ領域を生成する際に、レジストリの設定値に従って決定します。celog.dll は、共有メモリ上のリングバッファ構造体のヘッダにバッファサイズを書き込むことにより、CeLogFlush.exe にサイズを伝えます。CeLogFlush.exe は、リングバッファが満杯に近付かなくとも(つまり、celog.dll から event オブジェクトで通知されなくとも)、レジストリで設定されたタイムアウト時間が経過すると、リングバッファの内容をファイルへ出力します。従って、ログ出力の量が少ない場合でも、一定周期でログファイルへの書き出しが行われます。

(2)”Enable event tracking during boot” を設定しない場合の動作
 OS Design の「構成プロパティ」の Build Options で、”Enable event tracking during boot” を Yes (IMGCELOGENABLE=1) に設定しない場合とする場合の違いについて、もう少し詳しく述べておきます。

  IMGCELOGENABLE を1に設定した場合としない場合の違いは、WEC/WinCE カーネルの初期化が完了した後から、カーネルの起動が完了するまでの間のログ出力を採取するかどうかです。つまり、IMGCELOGENABLE を1に設定した場合は、CeLogFlush.exe が起動する前に出力されたログも採取できるのに対し、IMGCELOGENABLE を1に設定しない場合は、CeLogFlush.exe が起動した以降のログのみ採取可能となります。この違いは、celog.dll がロードされるタイミングの違いによって生じます。そのタイミングの違いを引き起こすのは、.bib ファイルの設定です。

  WEC 7 の場合、common.bib の設定で、IMGAUTOFLUSH のみ1に設定した場合(IMGCELOGENABLE は1に設定しない場合)は、celog.dll が .bib ファイルの MODULES セクションではなく、FILES セクションに配置されると述べました。この結果、WEC/WinCE カーネルの初期化が完了した直後のタイミングでは、celog.dll がロードされず、CeLogFlush.exe によって初めてロードされるのです。これについて、もう少しだけ詳しく述べます。

  WEC/WinCE カーネルの初期化が終わり、マルチスレッドモードへ遷移して最初に起動されるスレッドが実行する関数である SystemStartupFunc() の中で、LoggerInit() という、ログ機能の初期化関数を呼び出します。この LoggerInit() は、”CeLog.dll” を引数として LoadKernelLibrary() を呼び出し、celog.dll をカーネルにロードすることを要求します。しかし、この時点では、filesys.dll がロードされておらず、ファイルシステム機能が初期化されていません。そのため、カーネルの loader は、OS イメージの中の modules、つまり、.bib ファイルの MODULES セクションに配置された DLL しかロードできないのです(※ちなみに、SystemStartupFunc() は、LoggerInit() を呼び出す前に、LoaderInit() を呼び出してカーネルの loader を初期化します)。そのため、LoggerInit() による CeLog.dll のロードは成功せず、その時点では、ログ出力が有効になりません。その後、CeLogFlush.exe が起動すると、CeLogFlush.exe の初期化処理において、再び “CeLog.dll” を引数として LoadKernelLibrary() が呼び出されます。この時点では、filesys.dll が動作していますので、FILES セクションに配置された DLL もロードできる、というわけです。

  さて、celog.dll は、ロードされると、InitLibrary() という初期化関数を呼び出します。この関数の中で、IOCTL_CELOG_REGISTER を ioctl コードとする KernelLibIoControl() 呼び出しを行い、ログ出力関数群の関数テーブル(CeLogExportTable 構造体)をカーネル本体に登録します。これらの関数は、カーネル本体の中にあるログ出力部に登録されます。カーネル本体の中にあるログ出力部は、登録された関数テーブルの中の pfnCeLogQueryZones というメンバを使って、ログ出力 DLL から、出力対象とする zone の組み合わせを示すマスクビット列を得て、ログ出力の有無判定に使う、という仕組みになっています。

  上で述べた、カーネル本体の処理のソースコードは、それぞれ次の場所にあります:

  SystemStartupFunc()
  %_WINCEROOT%/private/winceos/COREOS/nk/celog/schedule.c

  カーネル本体の中のログ出力部
  %_WINCEROOT%/private/winceos/COREOS/nk/logger/logger.c

(3)Readlog
  Kernel Tracker を使うと、WEC/WinCE カーネルのログ機能が出力したログデータをグラフィカルに表示できることを、冒頭で紹介しました。このログデータ、つまり .clg ファイルの内容を解析する付属のツールは、他にもあります。それが Readlog です。Readlog について、リファレンスの次のページをご覧下さい:

  Readlog Viewing Tool (Windows Embedded Compact 7)
  http://msdn.microsoft.com/en-us/library/ee481220.aspx

  Readlog Viewing Tool (Windows Embedded CE 6.0)
  http://msdn.microsoft.com/en-US/library/ee481220(v=winembedded.60)

  スレッドの切り替わりの様子などを直観的に見るには、Kernel Tracker が便利ですが、Kernel Tracker には表示されないログ内容をチェックしたり、ログ全体の分析結果などを手早く表示するには、Readlog の方が便利です。ちなみに、WinCE 6.0 の Kernel Tracker では、”Thread Migrate” のログを表示できませんが、WEC 7 のものでは表示できます。この “Thread Migrate” は、システムコールの発生、つまり、プロセス(カーネルである nk.exe 以外のプロセス)中のスレッドの、カーネル呼び出しによる、ユーザモードとカーネルモードの間の遷移に伴うコンテキストスイッチを示します。

(4)ログ機能のカスタマイズ
  ここまでの説明では、WEC/WinCE カーネルのログ出力は、celog.dll によって実行されると述べました。しかし、celog.dll を使わず、独自のログ出力 DLL を実装して使うことが可能です。また、独自のログ出力 DLL を celog.dll と共存させることも可能です(複数のログ出力 DLL を共存させることに意味があるかどうかは、別としてですが)。

  独自のログ出力 DLL を実装する方法について、リファレンスの次のページで説明されています。今のところ、WinCE 6.0 向けのものしかありませんが、WEC 7 でも同様の筈です。興味のある方は、カーネル本体のログ出力部や celog.dll のソースコードと併せ、ご覧になってみて下さい。

  CeLog Tool Customization (Windows Embedded CE 6.0)
  http://msdn.microsoft.com/en-us/library/ee480013(v=winembedded.60)

  Implementing a Custom Event Tracking Library (Windows Embedded CE 6.0)
  http://msdn.microsoft.com/en-US/library/ee480279(v=winembedded.60)

  Implementing an Event Tracking Library (Windows Embedded CE 6.0)
  http://msdn.microsoft.com/en-US/library/ee480272(v=winembedded.60)

Add comment 2012/08/16 koga


Categories

Links

Posts by Authors

Recent Posts

Calendar

2012年8月
« 7月   12月 »
 1234
567891011
12131415161718
19202122232425
262728293031  

Posts by Month

Posts by Category

Meta