feat: Add VM instruction statistics and fix plugin TLV debugging

Major changes:
- Add --vm-stats and --vm-stats-json CLI flags for VM instruction profiling
- Implement instruction counting by opcode type with JSON output support
- Add enhanced TLV debug logging with NYASH_DEBUG_PLUGIN=1 environment variable
- Fix missing fields in CliConfig and ASTNode::BoxDeclaration for test compatibility
- Improve plugin method call error messages with argument count/type details

This enables MIR→VM conversion health checks and supports the Phase 8.6 VM optimization goals.

🤖 Generated with [Claude Code](https://claude.ai/code)

Co-Authored-By: Claude <noreply@anthropic.com>

docs/development/current/CURRENT_TASK.md

@@ -1,58 +1,51 @@
-# 🎯 CURRENT TASK - 2025年8月20日
+# 🎯 CURRENT TASK - 2025年8月23日（刷新）
 
-## 📊 現在の状況
+## ✅ 直近の完了
+1. ドキュメント再編成の完了（構造刷新）
+2. プラグインBox（FileBox）基本実装とインタープリター統合
+3. VM命令カウンタ＋時間計測のCLI化（`--vm-stats`, `--vm-stats-json`）とJSON出力対応
 
-### ✅ 完了したタスク
+## 🚧 次にやること（再開方針）
-1. **ドキュメント再編成** - 完全完了！
-   - 283ファイル → 4大カテゴリに整理
-   - Phaseファイルも統合済み
-   - 説明書/予定フォルダ削除済み
 
-2. **プラグインBox基本実装** (Phase 9.78c)
+1) MIR→VMの健全化（短期・最優先）
-   - FileBoxプラグイン実装済み
+- 現行MIR→VMのマッピング表を作成（欠落/冗長/重複を可視化）
-   - インタープリター経由の呼び出し成功
+- サンプル/テストをVMで実行し、差分ログ（例外系・returns_result）を確認
-   - 基本的な引数/戻り値サポート追加（ChatGPT5による）
+- 成果物: `docs/reference/architecture/mir-to-vm-mapping.md`（暫定）
 
-### 🚧 現在の課題
+2) VM×プラグインシステムのE2E検証（短期）
-1. **Bashコマンドエラー問題**
+- `tests/e2e_plugin_filebox.rs` をVMでも通す（`--features plugins`）
-   - docs整理で現在のディレクトリが削除された影響
+- ケース: `new/close`, `open/read/write`, `copyFrom(handle)`、デリゲーション from Parent
-   - セッション再起動が必要かも
+- 成果物: テストグリーン＋既知の制約を `VM_README.md` に明記
 
-2. **E2Eテスト状況**（tests/e2e_plugin_filebox.rs）
+3) 命令セットのダイエット（中期：目標26命令）
-   - インタープリターテスト: ✅ 成功（FileBox.close()が"ok"を返す）
+- 実行統計（`--vm-stats --vm-stats-json`）でホット命令を特定
-   - デリゲーションテスト: ❓ 未実装の可能性
+- 統合方針（例: TypeCheck/Castの整理、Array/Ref周りの集約、ExternCall→BoxCall移行）
-   - VMテスト: ❌ 失敗（VMはまだプラグインBox未対応）
+- 段階移行（互換エイリアス→削除）と回帰テスト整備
+- 成果物: 26命令案ドラフト＋移行計画
 
-### 🎯 次のタスク（MIR→VM チェック / 命令最適化）
+## ▶ 実行コマンド例
 
-1) MIR→VM 変換の健全性チェック（短期）
+計測実行:
-- 現行 MIR 命令 → VM 命令のマッピング表を作成
+```bash
-- E2E/サンプルを VM バックエンドで実行し、MIR→VM 変換ログを収集
+nyash --backend vm --vm-stats --vm-stats-json local_tests/test_hello.nyash > vm_stats.json
-- 例外系・Result正規化（returns_result）の経路を VM で確認
+```
 
-2) 命令使用実績の計測（短期）
+VM×プラグインE2E:
-- 実際に使用されている VM 命令を計測（実行ログ/カウンタ）
+```bash
-- 現行宣言33命令 → 実使用コア命令の抽出
+cargo test -q --features plugins e2e_interpreter_plugin_filebox_close_void
+cargo test -q --features plugins e2e_vm_plugin_filebox_close_void
+```
 
-3) 命令セットのダイエット検討（中期）
+MIRダンプ/検証:
-- 目標: 26命令（docsの合意値）
+```bash
-- 代替可能/統合可能な命令の提案と互換性影響の洗い出し
+nyash --dump-mir --mir-verbose examples/plugin_box_sample.nyash
-- 実験フラグで26命令版のVMを試作（段階移行）
+nyash --verify examples/plugin_box_sample.nyash
+```
 
-4) ドキュメント更新（短期）
+## 🔭 26命令ターゲット（ドラフトの方向性）
-- 現状の命令一覧と目標26命令の整合（reference/architecture/）
+コア（候補）: Const / Copy / Load / Store / BinOp / UnaryOp / Compare / Jump / Branch / Phi / Call / BoxCall / NewBox / ArrayGet / ArraySet / RefNew / RefGet / RefSet / WeakNew / WeakLoad / BarrierRead / BarrierWrite / Return / Print or ExternCall(→BoxCall集約) + 2枠（例外/await系のどちらか）
-- 計測結果（使用頻度）と統合方針を追記
 
-### 📝 メモ
+補助: Debug/Nop/Safepointはビルドモードで有効化（命令としては非中核に降格）
-- ChatGPT5がプラグインBoxメソッド呼び出しに引数/戻り値サポートを追加
-- TLV (Type-Length-Value) エンコーディングで引数をプラグインに渡す実装
-- Rustの借用チェッカーとの格闘の跡が見られる（複数回の修正）
-
-### 🔧 推奨アクション
-1. VMバックエンドでの実行ログ化（命令発行ログ/カウンタ）
-2. マッピング表作成（MIR→VM）と欠落/冗長命令の洗い出し
-3. 26命令案のPoCブランチ作成→E2Eで回帰確認
-4. docs更新（命令一覧、設計意図、移行戦略）
 
 ---
-最終更新: 2025年8月22日 03:30（MIR→VM/命令最適化タスク追加）
+最終更新: 2025年8月23日（MIR/VM再フォーカス、26命令ダイエットへ）

src/backend/vm.rs

@@ -13,6 +13,7 @@ use crate::scope_tracker::ScopeTracker;
 // MirModule is already imported via crate::mir at top
 use crate::instance_v2::InstanceBox;
 use super::vm_phi::LoopExecutor;
+use std::time::Instant;
 
 // Phase 9.78a: Import necessary components for unified Box handling
 // TODO: Re-enable when interpreter refactoring is complete
@@ -185,6 +186,10 @@ pub struct VM {
     scope_tracker: ScopeTracker,
     /// Active MIR module during execution (for function calls)
     module: Option<MirModule>,
+    /// Instruction execution counters (by MIR opcode)
+    instr_counter: std::collections::HashMap<&'static str, usize>,
+    /// Execution start time for optional stats
+    exec_start: Option<Instant>,
     // Phase 9.78a: Add unified Box handling components
     // TODO: Re-enable when interpreter refactoring is complete
     // /// Box registry for creating all Box types
@@ -215,6 +220,8 @@ impl VM {
             runtime: NyashRuntime::new(),
             scope_tracker: ScopeTracker::new(),
             module: None,
+            instr_counter: std::collections::HashMap::new(),
+            exec_start: None,
             // TODO: Re-enable when interpreter refactoring is complete
             // box_registry: Arc::new(UnifiedBoxRegistry::new()),
             // #[cfg(all(feature = "plugins", not(target_arch = "wasm32")))]
@@ -240,6 +247,8 @@ impl VM {
             runtime,
             scope_tracker: ScopeTracker::new(),
             module: None,
+            instr_counter: std::collections::HashMap::new(),
+            exec_start: None,
         }
     }
     
@@ -270,6 +279,9 @@ impl VM {
     pub fn execute_module(&mut self, module: &MirModule) -> Result<Box<dyn NyashBox>, VMError> {
         // Store module for nested calls
         self.module = Some(module.clone());
+        // Reset stats
+        self.instr_counter.clear();
+        self.exec_start = Some(Instant::now());
         // Find main function
         let main_function = module.get_function("main")
             .ok_or_else(|| VMError::InvalidInstruction("No main function found".to_string()))?;
@@ -277,6 +289,9 @@ impl VM {
         // Execute main function
         let result = self.execute_function(main_function)?;
         
+        // Optional: print VM stats
+        self.maybe_print_stats();
+
         // Convert result to NyashBox
         Ok(result.to_nyash_box())
     }
@@ -392,6 +407,8 @@ impl VM {
     
     /// Execute a single instruction
     fn execute_instruction(&mut self, instruction: &MirInstruction) -> Result<ControlFlow, VMError> {
+        // Record instruction for stats
+        self.record_instruction(instruction);
         match instruction {
             MirInstruction::Const { dst, value } => {
                 let vm_value = VMValue::from(value);
@@ -985,6 +1002,90 @@ impl VM {
             _ => Err(VMError::TypeError(format!("Unsupported comparison: {:?} on {:?} and {:?}", op, left, right))),
         }
     }
+
+    /// Record an instruction execution for statistics
+    fn record_instruction(&mut self, instruction: &MirInstruction) {
+        let key: &'static str = match instruction {
+            MirInstruction::Const { .. } => "Const",
+            MirInstruction::BinOp { .. } => "BinOp",
+            MirInstruction::UnaryOp { .. } => "UnaryOp",
+            MirInstruction::Compare { .. } => "Compare",
+            MirInstruction::Load { .. } => "Load",
+            MirInstruction::Store { .. } => "Store",
+            MirInstruction::Call { .. } => "Call",
+            MirInstruction::BoxCall { .. } => "BoxCall",
+            MirInstruction::Branch { .. } => "Branch",
+            MirInstruction::Jump { .. } => "Jump",
+            MirInstruction::Return { .. } => "Return",
+            MirInstruction::Phi { .. } => "Phi",
+            MirInstruction::NewBox { .. } => "NewBox",
+            MirInstruction::TypeCheck { .. } => "TypeCheck",
+            MirInstruction::Cast { .. } => "Cast",
+            MirInstruction::ArrayGet { .. } => "ArrayGet",
+            MirInstruction::ArraySet { .. } => "ArraySet",
+            MirInstruction::Copy { .. } => "Copy",
+            MirInstruction::Debug { .. } => "Debug",
+            MirInstruction::Print { .. } => "Print",
+            MirInstruction::Nop => "Nop",
+            MirInstruction::Throw { .. } => "Throw",
+            MirInstruction::Catch { .. } => "Catch",
+            MirInstruction::Safepoint => "Safepoint",
+            MirInstruction::RefNew { .. } => "RefNew",
+            MirInstruction::RefGet { .. } => "RefGet",
+            MirInstruction::RefSet { .. } => "RefSet",
+            MirInstruction::WeakNew { .. } => "WeakNew",
+            MirInstruction::WeakLoad { .. } => "WeakLoad",
+            MirInstruction::BarrierRead { .. } => "BarrierRead",
+            MirInstruction::BarrierWrite { .. } => "BarrierWrite",
+            MirInstruction::FutureNew { .. } => "FutureNew",
+            MirInstruction::FutureSet { .. } => "FutureSet",
+            MirInstruction::Await { .. } => "Await",
+            MirInstruction::ExternCall { .. } => "ExternCall",
+        };
+        *self.instr_counter.entry(key).or_insert(0) += 1;
+    }
+
+    /// Print simple VM execution statistics when enabled via env var
+    fn maybe_print_stats(&mut self) {
+        let enabled = std::env::var("NYASH_VM_STATS").ok().map(|v| v != "0").unwrap_or(false);
+        if !enabled { return; }
+
+        let elapsed_ms = self.exec_start.map(|t| t.elapsed().as_secs_f64() * 1000.0).unwrap_or(0.0);
+        let mut items: Vec<(&str, usize)> = self.instr_counter.iter().map(|(k,v)| (*k, *v)).collect();
+        items.sort_by(|a,b| b.1.cmp(&a.1).then_with(|| a.0.cmp(&b.0)));
+        let total: usize = items.iter().map(|(_,v)| *v).sum();
+
+        let json_enabled = std::env::var("NYASH_VM_STATS_JSON").ok().map(|v| v != "0").unwrap_or(false)
+            || std::env::var("NYASH_VM_STATS_FORMAT").map(|v| v == "json").unwrap_or(false);
+
+        if json_enabled {
+            // Build JSON structure: { total, elapsed_ms, counts: {op: n, ...}, top20: [{op, count}], timestamp_ms }
+            let counts_obj: std::collections::BTreeMap<&str, usize> = self.instr_counter.iter().map(|(k,v)| (*k, *v)).collect();
+            let top20: Vec<_> = items.iter().take(20).map(|(op,cnt)| {
+                serde_json::json!({ "op": op, "count": cnt })
+            }).collect();
+            let now_ms = {
+                use std::time::{SystemTime, UNIX_EPOCH};
+                SystemTime::now().duration_since(UNIX_EPOCH).map(|d| d.as_millis() as u64).unwrap_or(0)
+            };
+            let payload = serde_json::json!({
+                "total": total,
+                "elapsed_ms": elapsed_ms,
+                "counts": counts_obj,
+                "top20": top20,
+                "timestamp_ms": now_ms
+            });
+            match serde_json::to_string_pretty(&payload) {
+                Ok(s) => println!("{}", s),
+                Err(_) => println!("{{\"total\":{},\"elapsed_ms\":{:.3}}}", total, elapsed_ms),
+            }
+        } else {
+            println!("\n🧮 VM Stats: {} instructions in {:.3} ms", total, elapsed_ms);
+            for (k, v) in items.into_iter().take(20) {
+                println!("  {:>10}: {:>8}", k, v);
+            }
+        }
+    }
     
     /// Phase 9.78a: Unified method dispatch for all Box types
     fn call_unified_method(&self, box_value: Box<dyn NyashBox>, method: &str, args: Vec<Box<dyn NyashBox>>) -> Result<Box<dyn NyashBox>, VMError> {

src/cli.rs

@@ -21,6 +21,8 @@ pub struct CliConfig {
     pub output_file: Option<String>,
     pub benchmark: bool,
     pub iterations: u32,
+    pub vm_stats: bool,
+    pub vm_stats_json: bool,
 }
 
 impl CliConfig {
@@ -112,6 +114,18 @@ impl CliConfig {
                     .help("Number of iterations for benchmarks (default: 10)")
                     .default_value("10")
             )
+            .arg(
+                Arg::new("vm-stats")
+                    .long("vm-stats")
+                    .help("Enable VM instruction statistics (equivalent to NYASH_VM_STATS=1)")
+                    .action(clap::ArgAction::SetTrue)
+            )
+            .arg(
+                Arg::new("vm-stats-json")
+                    .long("vm-stats-json")
+                    .help("Output VM statistics in JSON format")
+                    .action(clap::ArgAction::SetTrue)
+            )
     }
 
     /// Convert ArgMatches to CliConfig
@@ -128,6 +142,8 @@ impl CliConfig {
             output_file: matches.get_one::<String>("output").cloned(),
             benchmark: matches.get_flag("benchmark"),
             iterations: matches.get_one::<String>("iterations").unwrap().parse().unwrap_or(10),
+            vm_stats: matches.get_flag("vm-stats"),
+            vm_stats_json: matches.get_flag("vm-stats-json"),
         }
     }
 }
@@ -168,9 +184,11 @@ mod tests {
             output_file: None,
             benchmark: false,
             iterations: 10,
+            vm_stats: false,
+            vm_stats_json: false,
         };
         
         assert_eq!(config.backend, "interpreter");
         assert_eq!(config.iterations, 10);
     }
-}
+}

src/runner.rs

@@ -51,6 +51,15 @@ impl NyashRunner {
         
         // Try to initialize BID plugins from nyash.toml (best-effort)
         self.init_bid_plugins();
+
+        // Optional: enable VM stats via CLI flags
+        if self.config.vm_stats {
+            std::env::set_var("NYASH_VM_STATS", "1");
+        }
+        if self.config.vm_stats_json {
+            // Prefer explicit JSON flag over any default
+            std::env::set_var("NYASH_VM_STATS_JSON", "1");
+        }
         // Benchmark mode - can run without a file
         if self.config.benchmark {
             println!("📊 Nyash Performance Benchmark Suite");
@@ -926,6 +935,8 @@ mod tests {
             output_file: None,
             benchmark: false,
             iterations: 10,
+            vm_stats: false,
+            vm_stats_json: false,
         };
         
         let runner = NyashRunner::new(config);

src/runtime/plugin_loader_v2.rs

@@ -386,6 +386,14 @@ impl PluginBoxV2 {
                 let expected_args = box_conf.methods.get(method_name).and_then(|m| m.args.clone());
                 if let Some(exp) = expected_args.as_ref() {
                     if exp.len() != args.len() {
+                        eprintln!(
+                            "[PluginLoaderV2] InvalidArgs: {}.{} expects {} args, got {} (schema={:?})",
+                            box_type,
+                            method_name,
+                            exp.len(),
+                            args.len(),
+                            exp.iter().map(|a| a.kind_str()).collect::<Vec<_>>()
+                        );
                         return Err(BidError::InvalidArgs);
                     }
                 }
@@ -417,7 +425,8 @@ impl PluginBoxV2 {
                                         }
                                     }
                                     _ => {
-                                        // Unsupported kind in this minimal implementation
+                                        eprintln!("[PluginLoaderV2] InvalidArgs: unsupported kind '{}' for {}.{} arg[{}]",
+                                            kind, box_type, method_name, idx);
                                         return Err(BidError::InvalidArgs);
                                     }
                                 }
@@ -427,6 +436,8 @@ impl PluginBoxV2 {
                                 let is_string = a.as_any().downcast_ref::<StringBox>().is_some();
                                 let is_int = a.as_any().downcast_ref::<IntegerBox>().is_some();
                                 if !(is_string || is_int) {
+                                    eprintln!("[PluginLoaderV2] InvalidArgs: expected string/int for {}.{} arg[{}]",
+                                        box_type, method_name, idx);
                                     return Err(BidError::InvalidArgs);
                                 }
                             }
@@ -481,7 +492,15 @@ impl PluginBoxV2 {
                 buf
             };
             eprintln!("[VM→Plugin] call {}.{} recv_id={} returns_result={}", box_type, method_name, instance_id, returns_result);
-            if dbg_on() { eprintln!("[VM→Plugin] call {}.{} recv_id={} returns_result={}", box_type, method_name, instance_id, returns_result); }
+            if dbg_on() {
+                // Dump compact TLV header and first few bytes for diagnostics
+                let hdr_ver = u16::from_le_bytes([tlv_args[0], tlv_args[1]]);
+                let hdr_argc = u16::from_le_bytes([tlv_args[2], tlv_args[3]]);
+                let preview_len = std::cmp::min(tlv_args.len(), 64);
+                let preview: Vec<String> = tlv_args[..preview_len].iter().map(|b| format!("{:02X}", b)).collect();
+                eprintln!("[VM→Plugin] TLV ver={} argc={} bytes={} preview={}...",
+                    hdr_ver, hdr_argc, tlv_args.len(), preview.join(" "));
+            }
             let mut out = vec![0u8; 1024];
             let mut out_len: usize = out.len();
             let rc = unsafe {

tests/mir_phase6_lowering_ref_ops.rs

@@ -110,6 +110,8 @@ fn test_mir_phase6_lowering_ref_ops() {
     let ast = ASTNode::BoxDeclaration {
         name: "Main".to_string(),
         fields: vec![],
+        public_fields: vec![],
+        private_fields: vec![],
         methods: main_methods,
         constructors: HashMap::new(),
         init_fields: vec![],
@@ -209,4 +211,4 @@ fn test_mir_verification_phase6_ref_ops() {
             println!("⚠️  Continuing test despite verification issues (verifier may be incomplete)");
         }
     }
-}
+}

tests/mir_phase7_async_ops.rs

@@ -71,6 +71,8 @@ fn test_mir_phase7_basic_nowait_await() {
     let ast = ASTNode::BoxDeclaration {
         name: "Main".to_string(),
         fields: vec![],
+        public_fields: vec![],
+        private_fields: vec![],
         methods: main_methods,
         constructors: HashMap::new(),
         init_fields: vec![],
@@ -228,6 +230,8 @@ fn test_mir_phase7_multiple_nowait_await() {
     let ast = ASTNode::BoxDeclaration {
         name: "Main".to_string(),
         fields: vec![],
+        public_fields: vec![],
+        private_fields: vec![],
         methods: main_methods,
         constructors: HashMap::new(),
         init_fields: vec![],
@@ -348,6 +352,8 @@ fn test_mir_phase7_nested_await() {
     let ast = ASTNode::BoxDeclaration {
         name: "Main".to_string(),
         fields: vec![],
+        public_fields: vec![],
+        private_fields: vec![],
         methods: main_methods,
         constructors: HashMap::new(),
         init_fields: vec![],
@@ -384,4 +390,4 @@ fn test_mir_phase7_nested_await() {
     
     // Should return 10 (5 * 2)
     assert_eq!(final_value.to_string_box().value, "10");
-}
+}