File: profiling.cpp

package info (click to toggle)
freespace2 3.7.4%2Brepack-1.1
  • links: PTS, VCS
  • area: non-free
  • in suites: bullseye
  • size: 22,268 kB
  • sloc: cpp: 393,535; ansic: 4,106; makefile: 1,091; xml: 181; sh: 137
file content (341 lines) | stat: -rw-r--r-- 10,024 bytes parent folder | download | duplicates (2)
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
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
/*
 * Copyright (C) Freespace Open 2013.  All rights reserved.
 *
 * All source code herein is the property of Freespace Open. You may not sell 
 * or otherwise commercially exploit the source or things you created based on the 
 * source.
 *
*/ 

#include "cmdline/cmdline.h"
#include "globalincs/pstypes.h"
#include "globalincs/systemvars.h"
#include "io/timer.h"

#include <fstream>

//======================CODE TO PROFILE PERFORMANCE=====================

/*
 * Usage information:
 * In order to gather profiling data for a single function call, you can use the PROFILE macro as defined in
 * pstypes.h.
 * Example:
 * PROFILE("Render", game_render_frame( cid ));
 * 
 * If you want to profile a block of function calls, you will need to use the profile_begin()/profile_end() calls.
 * Example:
 * profile_begin("Some Code");
 * ...some code...
 * profile_end("Some Code");
 * Note that the parameter passed MUST be globally unique across all instances of profiling invocations.
 *
 * Profiling invocations can be nested as deep as necessary; this will show up in the readout as indentations.
 */

SCP_vector<profile_sample> samples;
SCP_vector<profile_sample_history> history;

uint start_profile_time = 0;
uint end_profile_time = 0;

SCP_string profile_output;
std::ofstream profiling_file;

/**
 * @brief Called once at engine initialization to set the timer
 */
void profile_init()
{
	start_profile_time = timer_get_high_res_microseconds();

	if (Cmdline_profile_write_file)
	{
		profiling_file.open("profiling.csv");

		if (!profiling_file.good())
		{
			mprintf(("Failed to open profiling output file 'profiling.csv'!"));
		}
	}
}

void profile_deinit()
{
	if (Cmdline_profile_write_file)
	{
		if (profiling_file.is_open())
		{
			profiling_file.flush();
			profiling_file.close();
		}
	}
}

/**
 * Used to start profiling a section of code. A section started by profile_begin needs to be closed off by calling
 * profile_end with the same argument.
 * @param name A globally unique string that will be displayed in the HUD readout
 */
void profile_begin(const char* name)
{
	if (Cmdline_frame_profile)
	{
		int parent = -1;
		for (int i = 0; i < (int)samples.size(); i++) {
			if ( !samples[i].open_profiles ) {
				continue;
			}

			samples[i].num_children++;

			if (samples[i].num_children == 1) {
				// this is our direct parent for this new sample
				parent = i;
			}
		}

		for(int i = 0; i < (int)samples.size(); i++) {
			if( !strcmp(samples[i].name.c_str(), name) && samples[i].parent == parent ) {
				// found the profile sample
				samples[i].open_profiles++;
				samples[i].profile_instances++;
				samples[i].start_time = timer_get_high_res_microseconds();
				Assert(samples[i].open_profiles == 1); // max 1 open at once
				return;
			}
		}

		// create a new profile sample
		profile_sample new_sample;

		new_sample.name = SCP_string(name);
		new_sample.open_profiles = 1;
		new_sample.profile_instances = 1;
		new_sample.accumulator = 0;
		new_sample.start_time = timer_get_high_res_microseconds();
		new_sample.children_sample_time = 0;
		new_sample.num_children = 0;
		new_sample.parent = parent;

		samples.push_back(new_sample);
	}
}

/**
 * Used to end profiling of a section of code. Note that the parameter given MUST match that of the preceding call
 * to profile_begin
 * @param name A globally unique string that will be displayed in the HUD readout
 */
void profile_end(const char* name)
{
	if (Cmdline_frame_profile) {
		int num_parents = 0;
		int child_of = -1;

		for ( int i = 0; i < (int)samples.size(); i++ ) {
			if ( samples[i].open_profiles ) {
				if ( samples[i].num_children == 1 ) {
					child_of = i;
				}
			}
		}

		for ( int i = 0; i < (int)samples.size(); i++ ) {
			if ( !strcmp(samples[i].name.c_str(), name) && samples[i].parent == child_of ) {
				int inner = 0;
				int parent = -1;
				uint end_time = timer_get_high_res_microseconds();
				samples[i].open_profiles--;

				// count all parents and find the immediate parent
				while ( inner < (int)samples.size() ) {
					if ( samples[inner].open_profiles > 0 ) {
						// found a parent (any open profiles are parents)
						num_parents++;

						if (parent < 0) {
							// replace invalid parent (index)
							parent = inner;
						}
						else if (samples[inner].start_time >= samples[parent].start_time) {
							// replace with more immediate parent
							parent = inner;
						}
					}
					inner++;
				}

				// remember the current number of parents of the sample
				samples[i].num_parents = num_parents;

				if ( parent >= 0 ) {
					// record this time in children_sample_time (add it in)
					samples[parent].children_sample_time += end_time - samples[i].start_time;
				}

				// save sample time in accumulator
				samples[i].accumulator += end_time - samples[i].start_time;

				break;
			}
		}

		for (int i = 0; i < (int)samples.size(); i++) {
			if (samples[i].open_profiles) {
				samples[i].num_children--;
				samples[i].num_children = MAX(samples[i].num_children, 0);
			}
		}
	}
}

/**
 * Builds the output text.
 */
void profile_dump_output()
{
	if (Cmdline_frame_profile) {
		end_profile_time = timer_get_high_res_microseconds();

		if (Cmdline_profile_write_file)
		{
			profiling_file << end_profile_time << ";" << (end_profile_time - start_profile_time) << std::endl;
		}

		profile_output.clear();
		profile_output += "  Avg :  Min :  Max :   # : Profile Name\n";
		profile_output += "----------------------------------------\n";

		for(int i = 0; i < (int)samples.size(); i++) {
			uint sample_time;
			float percent_time, avg_time, min_time, max_time;
			uint avg_micro_seconds, min_micro_seconds, max_micro_seconds; 

			Assert(samples[i].open_profiles == 0);

			sample_time = samples[i].accumulator - samples[i].children_sample_time;

			if (end_profile_time == start_profile_time) {
				percent_time = 0.0f;
			} else {
				percent_time = (i2fl(sample_time) / i2fl(end_profile_time - start_profile_time)) *100.0f;
			}

			avg_micro_seconds = min_micro_seconds = max_micro_seconds = sample_time;
			avg_time = min_time = max_time = percent_time;

			// add new measurement into the history and get avg, min, and max
			store_profile_in_history(samples[i].name, percent_time, sample_time);
			get_profile_from_history(samples[i].name, &avg_time, &min_time, &max_time, &avg_micro_seconds, &min_micro_seconds, &max_micro_seconds);

			// format the data
			char avg[64], min[64], max[64], num[64];

			sprintf(avg, "%3.1f%% (%3.1fms)", avg_time, i2fl(avg_micro_seconds)*0.001f);
			sprintf(min, "%3.1f%% (%3.1fms)", min_time, i2fl(min_micro_seconds)*0.001f);
			sprintf(max, "%3.1f%% (%3.1fms)", max_time, i2fl(max_micro_seconds)*0.001f);
			sprintf(num, "%3d", samples[i].profile_instances);

			SCP_string indented_name(samples[i].name);

			for(uint indent = 0; indent < samples[i].num_parents; indent++) {
				indented_name = ">" + indented_name;
			}

			char line[256];
			sprintf(line, "%5s : %5s : %5s : %3s : ", avg, min, max, num);

			profile_output += line + indented_name + "\n";
		}

		samples.clear();
		start_profile_time = timer_get_high_res_microseconds();
	}
}

/**
 * Stores profile data in in the profile history lookup. This is used internally by the profiling code and should
 * not be called outside of it.
 * @param name The globally unique name for this profile (see profile_begin()/profile_end())
 * @param percent How much time the profiled section took to execute (as a percentage of overall frametime)
 */
void store_profile_in_history(SCP_string &name, float percent, uint time)
{
	float old_ratio;
	float new_ratio = 0.8f * f2fl(Frametime);

	if(new_ratio > 1.0f) {
		new_ratio = 1.0f;
	}

	old_ratio = 1.0f - new_ratio;

	for(int i = 0; i < (int)history.size(); i++) {
		if( history[i].valid && history[i].name == name ) {
			// found the sample
			history[i].avg = (history[i].avg * old_ratio) + (percent * new_ratio);
			history[i].avg_micro_sec = fl2i((history[i].avg_micro_sec * old_ratio) + (time * new_ratio));

			if( percent < history[i].min ) {
				history[i].min = percent;
			} else {
				history[i].min = (history[i].min*old_ratio) + (percent*new_ratio);
			}

			if( time < history[i].min_micro_sec ) {
				history[i].min_micro_sec = time;
			} else {
				history[i].min_micro_sec = fl2i((history[i].min_micro_sec*old_ratio) + (time*new_ratio));
			}

			if( percent > history[i].max) {
				history[i].max = percent;
			} else {
				history[i].max = (history[i].max * old_ratio) + (percent * new_ratio);
			}

			if( time > history[i].max_micro_sec) {
				history[i].max_micro_sec = time;
			} else {
				history[i].max_micro_sec = fl2i((history[i].max_micro_sec * old_ratio) + (time * new_ratio));
			}

			return;
		}
	}

	// add to history
	profile_sample_history new_history;

	new_history.name = name;
	new_history.valid = true;
	new_history.avg = new_history.min = new_history.max = percent;
	new_history.avg_micro_sec = new_history.min_micro_sec = new_history.max_micro_sec = time;

	history.push_back(new_history);
}

/**
 * Gets the min, max and average values for a given profile
 * @param name The globally unique name for this profile (see profile_begin()/profile_end())
 * @param avg Pointer to a float in which the average value will be stored (or 0.0 if no value has been saved)
 * @param min Pointer to a float in which the minimum value will be stored (or 0.0 if no value has been saved)
 * @param max Pointer to a float in which the maximum value will be stored (or 0.0 if no value has been saved)
 */
void get_profile_from_history(SCP_string &name, float* avg, float* min, float* max, uint *avg_micro_sec, uint *min_micro_sec, uint *max_micro_sec)
{
	for ( int i = 0; i < (int)history.size(); i++ ) {
		if ( history[i].name == name ) {
			*avg = history[i].avg;
			*min = history[i].min;
			*max = history[i].max;
			*avg_micro_sec = history[i].avg_micro_sec;
			*min_micro_sec = history[i].min_micro_sec;
			*max_micro_sec = history[i].max_micro_sec;
			return;
		}
	}

	*avg = *min = *max = 0.0f;
}