# 帳票設計書 6-@timeレポート

## 概要

本ドキュメントは、Julia の `@time` マクロによって出力されるパフォーマンス計測レポートの設計仕様を記述する。

### 本帳票の処理概要

本帳票は、Julia の `@time` マクロにより、式の実行に関するパフォーマンス情報を1行のサマリー形式で標準出力にレポートする。実行時間、メモリアロケーション量、GC 時間、コンパイル時間、ロック競合数を含むコンパクトなレポートである。

**業務上の目的・背景**：Julia プログラムの実行パフォーマンスを簡易的に計測するために、式の実行時間とメモリ使用状況を即座に確認できる手段が必要である。`@time` は最も基本的かつ頻繁に使用されるパフォーマンス計測ツールであり、REPL での対話的な開発やコードの最適化において不可欠である。

**帳票の利用シーン**：開発者が関数や式の実行パフォーマンスを素早く確認したい場合に使用する。初回実行時のコンパイル時間の影響を確認したり、アロケーションの有無を確認したりする場面で日常的に使用される。ループ内で繰り返し計測する使い方もサポートされる。

**主要な出力内容**：
1. 実行時間（秒、小数点以下6桁）
2. アロケーション数と総バイト数
3. GC 時間の割合（%）
4. ロック競合数（Julia 1.11以降）
5. コンパイル時間の割合（%）
6. リコンパイル時間の割合（%）

**帳票の出力タイミング**：`@time expr` または `@time "description" expr` が評価されたとき。

**帳票の利用者**：Julia プログラムの開発者全般。

## 帳票種別

サマリーレポート（1行形式のパフォーマンス計測結果）

## 利用画面

| 画面No | 画面名 | URL/ルーティング | 出力操作 |
|--------|--------|-----------------|---------|
| - | Julia REPL | julia> | `@time expr` を実行 |
| - | スクリプト | - | スクリプト内で `@time expr` を記述 |

## 出力形式

### 基本仕様

| 項目 | 内容 |
|-----|------|
| ファイル形式 | テキスト（標準出力） |
| 用紙サイズ | N/A |
| 向き | N/A |
| ファイル名 | N/A |
| 出力方法 | 標準出力（stdout）への1行出力 |
| 文字コード | UTF-8 |

## 帳票レイアウト

### レイアウト概要

`@time` の出力は1行のテキストで、以下のフォーマットとなる。

```
  0.606588 seconds (2.19 M allocations: 116.555 MiB, 3.75% gc time, 99.94% compilation time)
```

説明文字列付きの場合：

```
A one second sleep: 1.005750 seconds (5 allocations: 144 bytes)
```

ループカウンタ付きの場合：

```
1: 1.006760 seconds (5 allocations: 144 bytes)
```

### ヘッダー部

N/A（1行出力のためヘッダーなし）

### 明細部

| No | 項目名 | 説明 | データ取得元 | 表示形式 | 条件 |
|----|-------|------|-------------|---------|------|
| 1 | 説明文字列 | ユーザー指定の説明（オプション） | `msg` 引数 | `"{msg}: "` | msg が指定された場合のみ |
| 2 | 実行時間 | 式の実行にかかった時間 | `ret.time * 1e9` | `"{time} seconds"` 右寄せ10桁、小数6桁 | 常に表示 |
| 3 | アロケーション数 | 式実行中のアロケーション回数 | `gc_alloc_count(ret.gcstats)` | `"({count} allocations: "` | allocs > 0 の場合 |
| 4 | アロケーションバイト数 | 式実行中の総アロケーションバイト数 | `ret.gcstats.allocd` | `format_bytes()` | allocs > 0 の場合 |
| 5 | GC 時間 | GC に費やした時間の割合 | `ret.gcstats.total_time` | `"{pct}% gc time"` | gctime > 0 の場合 |
| 6 | ロック競合数 | ReentrantLock の競合回数 | `ret.lock_conflicts` | `"{n} lock conflict(s)"` | conflicts > 0 の場合 |
| 7 | コンパイル時間 | コンパイルに費やした時間の割合 | `ret.compile_time * 1e9` | `"{pct}% compilation time"` | compile_time > 0 の場合 |
| 8 | リコンパイル時間 | リコンパイルの割合 | `ret.recompile_time * 1e9` | `"{pct}% of which was recompilation"` | recompile_time > 0 の場合 |

### フッター部

N/A

## 出力条件

### 抽出条件

| 条件名 | 説明 | 必須 |
|-------|------|-----|
| expr | 計測対象の式 | Yes |
| msg | 説明文字列（オプション） | No |

### ソート順

N/A（1回の計測結果を出力）

### 改ページ条件

N/A

## データベース参照仕様

### 参照テーブル一覧

本帳票はデータベースを参照しない。ランタイム計測データを直接取得する。

| テーブル名 | 用途 | 結合条件 |
|-----------|------|---------|
| GC_Num（gc_num()） | GC 統計情報の取得 | - |
| cumulative_compile_time_ns | コンパイル時間の取得 | - |
| LOCK_CONFLICT_COUNT | ロック競合数の取得 | - |

### テーブル別参照項目詳細

#### GC_Num 構造体

| 参照項目（カラム名） | 帳票項目との対応 | 取得条件 | 備考 |
|-------------------|----------------|---------|------|
| allocd + deferred_alloc + total_allocd | アロケーションバイト数 | gc_total_bytes() | 差分計算 |
| malloc | malloc 呼び出し数 | GC_Diff | 差分計算 |
| realloc | realloc 呼び出し数 | GC_Diff | 差分計算 |
| poolalloc | プールアロケーション数 | GC_Diff | 差分計算 |
| bigalloc | ビッグアロケーション数 | GC_Diff | 差分計算 |
| total_time | GC 時間（ナノ秒） | GC_Diff | 差分計算 |

## 計算仕様

### 計算項目一覧

| 項目名 | 計算式 | 端数処理 | 備考 |
|-------|-------|---------|------|
| 実行時間 | `(time_ns() - t0) / 1e9` → `Ryu.writefixed(elapsedtime/1e9, 6)` | 小数6桁固定 | ナノ秒精度 |
| アロケーション数 | `gc_alloc_count(diff) = diff.malloc + diff.realloc + diff.poolalloc + diff.bigalloc` | なし | 整数 |
| アロケーションバイト | `diff.allocd` (= `gc_total_bytes(new) - gc_total_bytes(old)`) | なし | 整数 |
| GC 時間% | `100 * gctime / elapsedtime` | `Ryu.writefixed(..., 2)` | 小数2桁 |
| コンパイル時間% | `100 * compile_time / elapsedtime` | `Ryu.writefixed(..., 2)` | 小数2桁 |
| リコンパイル% | `100 * recompile_time / compile_time` | `Ryu.writefixed(..., 0)` または `"<1"` | 1%未満は"<1" |
| アロケーション数表示 | `prettyprint_getunits(allocs, 6, 1000)` | 適切な単位（k, M, G等） | 1000進 |
| バイト数表示 | `format_bytes(bytes)` | 1024進の適切な単位 | KiB, MiB等 |

## 処理フロー

### 出力フロー

```mermaid
flowchart TD
    A["@time expr 展開"] --> B["@timed expr 実行"]
    B --> C["Experimental.@force_compile"]
    C --> D["lock_profiling(true)"]
    D --> E["gc_num() で開始時GC統計取得"]
    E --> F["time_ns() で開始時刻取得"]
    F --> G["cumulative_compile_timing(true)"]
    G --> H["式の実行"]
    H --> I["time_ns() - t0 で経過時間計算"]
    I --> J["GC_Diff で差分計算"]
    J --> K["time_print() で1行出力"]
    K --> L["値を返却"]
```

## エラー処理

### エラーケース一覧

| エラー種別 | 発生条件 | 表示メッセージ | 対処方法 |
|----------|---------|--------------|---------|
| 式の実行エラー | 式の評価中に例外が発生 | 元の例外が伝播 | try-finally で計測は完了する |

## パフォーマンス要件

| 項目 | 内容 |
|-----|------|
| 想定データ件数 | 1回の計測 |
| 目標出力時間 | ほぼ即座（出力処理自体のオーバーヘッドは無視可能） |
| 同時出力数上限 | N/A |

## セキュリティ考慮事項

`@time` の出力にはセキュリティ上の懸念は少ない。ただし、説明文字列にユーザー入力を含める場合は、その内容に注意が必要。

## 備考

- Julia 1.8 以降で説明文字列のオプションが追加された。
- Julia 1.8 以降でリコンパイル時間が別途表示されるようになった。
- Julia 1.11 以降でロック競合数が表示されるようになった。
- より厳密なベンチマークには BenchmarkTools.jl の `@btime` が推奨される。
- `@showtime` は `@time` の変種で、式自体も出力する。
- `@timed` は同様の情報を NamedTuple として返す（出力せずにデータとして利用可能）。

---

## コードリーディングガイド

本帳票を理解するために参照すべきファイルと、推奨する読み解き順序を以下に示す。

### 推奨読解順序

#### Step 1: データ構造を理解する

| 順序 | ファイル | パス | 読解ポイント |
|-----|---------|------|-------------|
| 1-1 | timing.jl | `base/timing.jl` | `GC_Num` 構造体（行4-75）で GC 統計情報の全フィールドを理解する |
| 1-2 | timing.jl | `base/timing.jl` | `GC_Diff` 構造体（行80-90）で差分計算用の構造体を理解する |

**読解のコツ**: `GC_Num` は C の `src/gc-interface.h` の構造体と同期が必要。`GC_Diff` は `new - old` の差分を表す。

#### Step 2: エントリーポイントを理解する

| 順序 | ファイル | パス | 読解ポイント |
|-----|---------|------|-------------|
| 2-1 | timing.jl | `base/timing.jl` | `@time` マクロ（行393-406）で、`@timed` への展開を理解する |
| 2-2 | timing.jl | `base/timing.jl` | `@timed` マクロ（行730-758）で、計測の実装を理解する |

**主要処理フロー**:
1. **行400**: `@timed expr` を呼び出し
2. **行730-758**: `@timed` の実装 - `gc_num()`, `time_ns()`, `cumulative_compile_timing` 等で計測開始
3. **行739-745**: try-finally で式を実行し、終了時の統計を取得
4. **行403**: `time_print()` で1行出力

#### Step 3: 出力処理を理解する

| 順序 | ファイル | パス | 読解ポイント |
|-----|---------|------|-------------|
| 3-1 | timing.jl | `base/timing.jl` | `time_print()` 関数（行252-303）でフォーマット処理を理解する |
| 3-2 | timing.jl | `base/timing.jl` | `prettyprint_getunits()` 関数（行200-208）で単位変換を理解する |
| 3-3 | timing.jl | `base/timing.jl` | `format_bytes()` 関数（行241-250）でバイト数フォーマットを理解する |

**主要処理フロー**:
- **行254**: `Ryu.writefixed` で実行時間を小数6桁にフォーマット
- **行263**: 括弧付きの詳細情報出力開始
- **行265-273**: アロケーション情報のフォーマット
- **行274-279**: GC 時間のフォーマット
- **行280-286**: ロック競合数のフォーマット
- **行287-297**: コンパイル時間・リコンパイル時間のフォーマット

### プログラム呼び出し階層図

```
@time msg expr
    |
    +-- @timed expr
    |       |
    |       +-- Experimental.@force_compile
    |       +-- Threads.lock_profiling(true)
    |       +-- gc_num()                    # 開始時GC統計
    |       +-- time_ns()                   # 開始時刻
    |       +-- cumulative_compile_timing(true)
    |       +-- cumulative_compile_time_ns()
    |       +-- expr の実行
    |       +-- time_ns() - t0              # 経過時間
    |       +-- GC_Diff(gc_num(), stats)    # GC差分
    |       +-- lock_profiling(false)
    |
    +-- time_print(stdout, ...)
            |
            +-- Ryu.writefixed()            # 数値フォーマット
            +-- prettyprint_getunits()      # 単位変換
            +-- format_bytes()              # バイト数フォーマット
```

### データフロー図

```
[入力]                          [処理]                              [出力]

gc_num() (開始) ─┐
time_ns() (開始) ─┤
                  ├── expr 実行 ──> @timed の NamedTuple
gc_num() (終了) ─┤                        |
time_ns() (終了) ─┘                 time_print()
                                          |
                                   stdout (1行テキスト)
```

### 関連ファイル一覧

| ファイル | パス | 種別 | 役割 |
|---------|------|------|------|
| timing.jl | `base/timing.jl` | ソース | @time, @timed マクロ、time_print, GC_Num, GC_Diff, format_bytes |
