前の関連記事：LibreOffice5(154)数値フィールドコントロールのサービスとインターフェイスの一覧
Pythonマクロのログをログファイルに取得する
ログが膨大になってTerminalでは表示しきれないので、LinuxでもWindowsでもいずれもログをファイルに取得して解析することにします(LibreOffice5(144)ログを取得する方法のPython/UNO bridgeのメソッドコールのログと同じです)。
linuxBean(Ubuntu)で/tmp/mylogfileファイルにログを出力するとき。
export PYUNO_LOGLEVEL=ARGS
export PYUNO_LOGTARGET="file:///tmp/mylogfile"
WindowsのPowerShellでc:\_tmp\mylogfileファイルにログを出力するとき。
$env:PYUNO_LOGLEVEL="ARGS"
$env:PYUNO_LOGTARGET="file:///c:/_tmp/mylogfile"
Windowsのコマンドラインでc:\_tmp\mylogfileファイルにログを出力するとき。
set PYUNO_LOGLEVEL=ARGS
set PYUNO_LOGTARGET=file:///c:/_tmp/mylogfile
上記コマンドを実行したTerminalからLibreOfficeを起動してPythonマクロを実行するとmylogfile.xxxx(xxxxはプロセスID)というファイル名でログが出力されます。
ログファイルはマクロを起動した時点で作成され、マクロの実行中にログファイルを削除してしまうと以後マクロを再起動しないとログファイルは作成されませんでした。
マクロの実行合間にログファイルを編集して保存すると以後そのファイルにはログは出力されなくなりました。
なので、イベントで駆動するマクロを調べたいときなどは、イベント実行前にログファイルをみて時間を記録しておきます。
ログファイルを読む
出力されるのはUNO APIのメソッドのログのみですが、それでも膨大な量になります。
2018-08-11 11:07:04,093 [CALL,tid 1]: try uno->py[0x-642963d4].selectionChanged((com.sun.star.lang.EventObject){ Source = (com.sun.star.uno.XInterface)0x-618b2960 })
2018-08-11 11:07:04,093 [CALL,tid 1]: try py->uno[0x-64139dcc].getSelection()
2018-08-11 11:07:04,094 [CALL,tid 1]: success py->uno[0x-64139dcc].getSelection()=(com.sun.star.uno.XInterface)0x-5db5e1d8
ログファイルの各行はこのようになっており、年月日に続く時刻は秒まで表示され、そのあとコンマに続く3桁の数値はミリ秒かと思います。今回調べたいマクロに該当するログを抽出すると620行ありました。
ログファイルをCalcに読み込む
Calcを起動して、ファイル→開く、でログファイルを開くとテキストのインポートのダイアログがでてきます。
文字エンコーディングを正しく選択しないと日本語が文字化けします。
linuxBean14.04ではUTF-8で日本語が正しく表示されました(Windows10ではWindows-932)。
日にち、時間、ミリ秒を各セルに取得したいのですが、適当な区切り文字がないので、「区切りのオプション」を「固定長」に選択します。
すると「フィールド」のルーラー上をマウスでクリックすると区切りが自由に選択できるので、上図のように区切りを入れました。
Calcで1行当たりの時間を計算する
A列のヘッダーを右クリック→左に列を挿入を2回繰り返して、左に空列を挿入しました。
=DATEVALUE(C1)+TIMEVALUE(D1)+F1/86400000
B1セルにこの式を代入しました。
Calcの日付シリアル値は24時間を1としていて、1日は86400000ミリ秒なので、F列のミリ秒を1日に変換しています。
YYYY/M/D H:MM:SS.000
デフォルトの日付書式では秒以下は表示されていないので、ミリ秒まで表示されるようにセルの書式をこのように設定します。
=B2-B1
A2セルにはB列の上行との差を求める式を代入します。
H:MM:SS.000
セル書式はミリ秒までの時間を表示するように設定します。
A列とB列すべての行について同じようにします。
mylogfile.13536
(linuxBean14.04(VirtualBoxゲスト)、LibreOffice5.4.1.2)
30ミリ秒以上かかっている行の背景色を黄色にしています。
最後の行の時刻と最初の行の時刻の差をとってみると0:00:01.182、つまり1.182秒かかっています。
シートの描画に時間がかかるようで、実際はもう少し時間がかかっている感じです。
時間がかかっているステップを調べてみると以下のことをしている時でした。
クリックした行の上下に罫線を引くとき(全セルにNoneの罫線を引いて計算をクリアしている)(setPropertyValue()) 5回 合計237ms
文字列をセルに代入するとき(setString()) 2回 合計199ms
selectionChanged()メソッドの発火するとき 2回 合計344ms
シートにディスパッチコマンドでペーストするとき(executeDispathc()) 1回 合計36ms
これらを合計すると0.816秒もかかっています。
直前のUNO APIのメソッドの差をとっているだけなので、その間にPythonコードがあるとそれが時間ロスの原因になっている可能性はありますが、UNO API のメソッドの方が総じて遅いようなので、コードを書くときはなるべくUNO APIメソッドが少なくなるようにします。
ログを元に律速段階を減らす
今回ログをとったマクロはシートを切り替えると動作するもので、selectionChanged()メソッドは発火させる必要がないので、activeSpreadsheetChanged()メソッド内でSelectionChangeListenerをはずしてまた付け直すことにしました。
mylogfile3
ログを取り直すとselectionChanged()メソッドの発火回数が減少し、0.615秒に短縮しました。
ステップも620から444に減りました。
mylogfile4
(Windows10 Home, LibreOffice6.0.5)
同じマクロをWindows10(上記linuxBean14.04のホストOS)で実行するとステップは472あり、1.001秒かかりました。
linuxBeanのときと結果が異なるのはselectionChanged()メソッドの発火のタイミングがOSによって異なるのが原因のようです。
Windows10では、外したSelectionChangeListenerを付け直したときにもselectionChanged()メソッドが発火するのでステップ数が増えてしまっています。
0 件のコメント:
コメントを投稿