From b2f699e14f02ba503c7a70afc3e9b749ac61f3d7 Mon Sep 17 00:00:00 2001 From: "Kartik K. Agaram" Date: Sun, 28 May 2017 23:42:54 -0700 Subject: 3888 - beginnings of a profiler Time to make my ad hoc commented out code fragments a first-class feature. --- 020run.cc | 69 +++++++++++++++++++++++++++++++++++---------------- 026call.cc | 5 ++++ 054static_dispatch.cc | 3 ++- 101run_sandboxed.cc | 5 ++++ 4 files changed, 60 insertions(+), 22 deletions(-) diff --git a/020run.cc b/020run.cc index 15644843..9b20a61e 100644 --- a/020run.cc +++ b/020run.cc @@ -48,9 +48,6 @@ struct routine { :(before "End Globals") routine* Current_routine = NULL; -map Instructions_running; -map Locations_read; -map Locations_read_by_instruction; :(before "End Setup") Current_routine = NULL; @@ -65,7 +62,6 @@ void run(const recipe_ordinal r) { void run_current_routine() { while (should_continue_running(Current_routine)) { // beware: may modify Current_routine // Running One Instruction -//? Instructions_running[current_recipe_name()]++; if (current_instruction().is_label) { ++current_step_index(); continue; } trace(Initial_callstack_depth + Trace_stream->callstack_depth, "run") << to_string(current_instruction()) << end(); if (get_or_insert(Memory, 0) != 0) { @@ -138,6 +134,11 @@ int& current_step_index() { return Current_routine->running_step_index; } +//: hook replaced in a later layer +recipe_ordinal currently_running_recipe() { + return Current_routine->running_recipe; +} + //: hook replaced in a later layer const string& current_recipe_name() { return get(Recipe, Current_routine->running_recipe).name; @@ -231,23 +232,6 @@ else if (is_equal(*arg, "--trace")) { Start_tracing = true; } -:(code) -void dump_profile() { - for (map::iterator p = Instructions_running.begin(); p != Instructions_running.end(); ++p) { - cerr << p->first << ": " << p->second << '\n'; - } - cerr << "== locations read\n"; - for (map::iterator p = Locations_read.begin(); p != Locations_read.end(); ++p) { - cerr << p->first << ": " << p->second << '\n'; - } - cerr << "== locations read by instruction\n"; - for (map::iterator p = Locations_read_by_instruction.begin(); p != Locations_read_by_instruction.end(); ++p) { - cerr << p->first << ": " << p->second << '\n'; - } -} -:(before "End One-time Setup") -//? atexit(dump_profile); - :(code) void cleanup_main() { if (Save_trace && Trace_stream) { @@ -456,3 +440,46 @@ def main [ 1:num, 2:num <- copy 2 ,2 ] +mem: storing 2 in location 1 + +//:: Counters for trying to understand where Mu programs are spending their +//:: time. + +:(before "End Globals") +bool Run_profiler = false; +// We'll key profile information by recipe_ordinal rather than name because +// it's more efficient, and because later layers will show more than just the +// name of a recipe. +// +// One drawback: if you're clearing recipes your profile will be inaccurate. +// So far that happens in tests, and in `run-sandboxed` in a later layer. +map Instructions_running; +:(before "End Commandline Options(*arg)") +else if (is_equal(*arg, "--profile")) { + Run_profiler = true; +} +:(after "Running One Instruction") +if (Run_profiler) Instructions_running[currently_running_recipe()]++; +:(before "End One-time Setup") +atexit(dump_profile); +:(code) +void dump_profile() { + if (!Run_profiler) return; + if (Run_tests) { + cerr << "It's not a good idea to profile a run with tests, since tests can create conflicting recipes and mislead you. To try it anyway, comment out this check in the code.\n"; + return; + } + ofstream fout; + fout.open("profile.instructions"); + if (fout) { + for (map::iterator p = Instructions_running.begin(); p != Instructions_running.end(); ++p) { + fout << std::setw(9) << p->second << ' ' << header_label(p->first) << '\n'; + } + } + fout.close(); + // End dump_profile +} + +// overridden in a later layer +string header_label(const recipe_ordinal r) { + return get(Recipe, r).name; +} diff --git a/026call.cc b/026call.cc index 81012350..15e44d35 100644 --- a/026call.cc +++ b/026call.cc @@ -79,6 +79,11 @@ int& current_step_index() { assert(!Current_routine->calls.empty()); return current_call().running_step_index; } +:(replace{} "recipe_ordinal currently_running_recipe()") +recipe_ordinal currently_running_recipe() { + assert(!Current_routine->calls.empty()); + return current_call().running_recipe; +} :(replace{} "const string& current_recipe_name()") const string& current_recipe_name() { assert(!Current_routine->calls.empty()); diff --git a/054static_dispatch.cc b/054static_dispatch.cc index e73ab3f5..450d887f 100644 --- a/054static_dispatch.cc +++ b/054static_dispatch.cc @@ -566,10 +566,11 @@ def foo x:num -> y:num [ # number variant is preferred +mem: storing 35 in location 1 -:(code) +:(replace{} "string header_label(const recipe_ordinal r)") string header_label(const recipe_ordinal r) { return header_label(get(Recipe, r)); } +:(code) string header_label(const recipe& caller) { ostringstream out; out << "recipe " << caller.name; diff --git a/101run_sandboxed.cc b/101run_sandboxed.cc index 1904942f..06b1cb04 100644 --- a/101run_sandboxed.cc +++ b/101run_sandboxed.cc @@ -130,6 +130,7 @@ bool run_interactive(int address) { //: Carefully update all state to exactly how it was -- including snapshots. :(before "End Globals") +bool Run_profiler_stash = false; map Recipe_ordinal_snapshot_stash; map Recipe_snapshot_stash; map Type_ordinal_snapshot_stash; @@ -145,6 +146,8 @@ void run_code_begin(bool should_stash_snapshots) { // stuff to undo later, in run_code_end() Hide_errors = true; Disable_redefine_checks = true; + Run_profiler_stash = Run_profiler; + Run_profiler = false; if (should_stash_snapshots) stash_snapshots(); Save_trace_stream = Trace_stream; @@ -155,6 +158,8 @@ void run_code_begin(bool should_stash_snapshots) { void run_code_end() { Hide_errors = false; Disable_redefine_checks = false; + Run_profiler = Run_profiler_stash; + Run_profiler_stash = false; //? ofstream fout("sandbox.log"); //? fout << Trace_stream->readable_contents(""); //? fout.close(); -- cgit 1.4.1-2-gfad0 <hut@lavabit.com> 2011-10-10 21:12:21 +0200 api.commands: finished merging ext.command_parser into api' href='/akspecs/ranger/commit/CHANGELOG?h=v1.6.0&id=43226a26b7df6cb58f033dc3e3a3e03f755bad72'>43226a26 ^ 
5abcb148 ^

fc0c76f9 ^


5abcb148 ^

5abcb148 ^

5abcb148 ^

5abcb148 ^



fc0c76f9 ^



5abcb148 ^

fc0c76f9 ^


ef2b1e37 ^

2ed2d4f7 ^





b7b8f3a0 ^





c8f870cb ^




ef2b1e37 ^
















81f5ac9e ^

efd7c0c1 ^







cbcd3325 ^







81f5ac9e ^

cbcd3325 ^

d3bcb234 ^


cbcd3325 ^

81f5ac9e ^












cbcd3325 ^

90018274 ^





cbcd3325 ^

95e021ae ^


c928a9eb ^

95e021ae ^

cbcd3325 ^

95e021ae ^
















1
2

3
4
5

6
7
8
9
10

11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32

33
34
35
36

37
38
39
40
41
42
43
44
45
46
47

48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77

78

79

80
81

82

83

84

85
86
87

88
89
90

91

92
93

94

95
96
97
98
99

100
101
102
103
104

105
106
107
108

109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124

125

126
127
128
129
130
131
132

133
134
135
136
137
138
139

140

141

142
143

144

145
146
147
148
149
150
151
152
153
154
155
156

157

158
159
160
161
162

163

164
165

166

167

168

169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184