// time an individual event
void timing_event_start(char *event_name)
{
#ifndef USE_TIMING
return;
#else
int event;
// sanity
if(event_name == NULL){
return;
}
// try and find the event
event = timing_event_lookup(event_name);
// if we already have one
if(event != -1){
Assert(Timing_events[event].ref_count == 0);
Timing_events[event].start = timer_get_microseconds();
Timing_events[event].ref_count++;
}
// if we need to add a new one
else {
if(Timing_event_count < MAX_TIMING_EVENTS){
strcpy_s(Timing_events[Timing_event_count].name, event_name);
Timing_events[Timing_event_count].start = timer_get_microseconds();
Timing_events[Timing_event_count++].ref_count++;
}
}
#endif
}
/**
* Builds the output text.
*/
void profile_dump_output()
{
if (Cmdline_frame_profile) {
end_profile_time = timer_get_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++) {
uint64_t sample_time;
float percent_time, avg_time, min_time, max_time;
uint64_t 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_microseconds();
}
}
static void mve_timer_start(void)
{
timer_expire = static_cast<int>(timer_get_microseconds());
timer_expire += micro_frame_delay;
timer_started = 1;
}
int timer_get_seconds()
{
if (!Timer_inited) {
Int3();
return 0;
}
return (int) (timer_get_microseconds() / MICROSECONDS_PER_SECOND);
}
int timer_get_milliseconds()
{
if (!Timer_inited) {
Int3(); // Make sure you call timer_init before anything that uses timer functions!
return 0;
}
return (int) (timer_get_microseconds() / 1000);
}
fix timer_get_fixed_seconds()
{
if (!Timer_inited) {
Int3(); // Make sure you call timer_init before anything that uses timer functions!
return 0;
}
auto time = timer_get_microseconds();
time *= 65536;
return (fix)(time / MICROSECONDS_PER_SECOND);
}
void main (void)
{
unsigned int MyTimer, t,t1, t2, ot, myc;
int i,s, b;
key_init();
//timer_init( 4661, NULL );
timer_init( 0, NULL );
s = TICKER;
MyTimer = timer_get_microseconds();
while(!keyd_pressed[KEY_ESC])
{
delay(1);
ot =t;
t = timer_get_milliseconds();
t1 = (TICKER - s)*10000/182;
//printf( "%d\t%d\t%u\t%d\t%u\t%u\t%u\n", (TICKER-s)*10000/182, myc, t, (int)t-(int)ot, key_down_time(KEY_G), key_down_count(KEY_G), key_up_count(KEY_G) );
printf( "%u\t%u\t%d\n", t1, t, (int)t - (int)t1 );
}
t1 = timer_get_microseconds();
delay(100);
t2 = timer_get_microseconds();
printf( "This number should be about 100000: %d\n", t2-t1 );
t1 = timer_get_microseconds();
t2 = timer_get_microseconds();
printf( "Overhead for 'timer_get_microseconds' call: %d æSeconds\n", t2-t1 );
timer_close();
}
// done timing the frame
void timing_frame_stop()
{
#ifndef USE_TIMING
return;
#else
int stop_time;
// stop time
stop_time = timer_get_microseconds();
// calc times
Timing_frame.microseconds_total = stop_time - Timing_frame.start;
#endif
}
// start timing frame stuff
void timing_frame_start()
{
#ifndef USE_TIMING
return;
#else
int idx;
// restart the frame
Timing_event_count = 0;
Timing_frame.start = timer_get_microseconds();
for(idx=0; idx<MAX_TIMING_EVENTS; idx++){
Timing_events[idx].microseconds_total = 0;
strcpy_s(Timing_events[idx].name, "");
Timing_events[idx].ref_count = 0;
}
#endif
}
/**
* @brief Called once at engine initialization to set the timer
*/
void profile_init()
{
start_profile_time = timer_get_microseconds();
if (Cmdline_profile_write_file)
{
profiling_file.open("profiling.csv");
if (!profiling_file.good())
{
mprintf(("Failed to open profiling output file 'profiling.csv'!"));
}
}
if (Cmdline_json_profiling) {
_mkdir("tracing");
}
}
static void mve_timer_start(void)
{
#ifdef SCP_UNIX
int nsec = 0;
gettimeofday(&timer_expire, NULL);
timer_expire.tv_usec += micro_frame_delay;
if (timer_expire.tv_usec > 1000000) {
nsec = timer_expire.tv_usec / 1000000;
timer_expire.tv_sec += nsec;
timer_expire.tv_usec -= nsec * 1000000;
}
#else
timer_expire = timer_get_microseconds();
timer_expire += micro_frame_delay;
#endif
timer_started = 1;
}
// stop timing an event
void timing_event_stop(char *event_name)
{
#ifndef USE_TIMING
return;
#else
int event;
// sanity
if(event_name == NULL){
return;
}
// try and find the event
event = timing_event_lookup(event_name);
// if we already have one
if(event != -1){
Assert(Timing_events[event].ref_count == 1);
Timing_events[event].microseconds_total += timer_get_microseconds() - Timing_events[event].start;
Timing_events[event].ref_count--;
}
#endif
}
static int mve_do_timer_wait(void)
{
if (!timer_started) {
return 0;
}
int tv, ts, ts2;
tv = static_cast<int>(timer_get_microseconds());
if (tv > timer_expire) {
goto end;
}
ts = timer_expire - tv;
ts2 = ts/1000;
os_sleep(ts2);
end:
timer_expire += micro_frame_delay;
return 0;
}
void main (void)
{
unsigned int t1, t2;
int i, start, stop, frames;
short bd1, bd2, bu1, bu2, b, x, y, bt1, bt2;
key_init();
if (!joy_init()) {
printf( "No joystick detected.\n" );
key_close();
exit(1);
}
timer_init( 0, NULL );
printf( "Displaying joystick button transitions and time...any key leaves.\n" );
i = 0;
while( !key_inkey() )
{
i++;
if (i>500000) {
i = 0;
joy_get_btn_down_cnt( &bd1, &bd2 );
joy_get_btn_up_cnt( &bu1, &bu2 );
joy_get_btn_time( &bt1, &bt2 );
printf( "%d %d %d %d T1:%d T2:%d\n",bd1, bu1, bd2, bu2, bt1, bt2 );
}
}
printf( "\nPress c to do a deluxe-full-fledged calibration.\n" );
printf( "or any other key to just use the cheap method.\n" );
if (key_getch() == 'c') {
printf( "Move stick to center and press any key.\n" );
wait();
joy_set_cen();
printf( "Move stick to Upper Left corner and press any key.\n" );
wait();
joy_set_ul();
printf( "Move stick to Lower Right corner and press any key.\n" );
wait();
joy_set_lr();
}
while( !keyd_pressed[KEY_ESC])
{
frames++;
joy_get_pos( &x, &y );
b = joy_get_btns();
printf( "%d, %d (%d %d)\n", x, y, b & 1, b & 2);
}
printf( "Testing joystick reading speed...\n" );
t1 = timer_get_microseconds();
joy_get_pos( &x, &y );
t2 = timer_get_microseconds();
printf( "~ %u æsec per reading using Timer Timing\n", t2 - t1 );
joy_close();
key_close();
timer_close();
frames = 1000;
start = TICKER;
for (i=0; i<frames; i++ )
joy_get_pos( &x, &y );
stop = TICKER;
printf( "~ %d æsec per reading using BIOS ticker as a stopwatch.\n", USECS_PER_READING( start, stop, frames ) );
}
main()
{
unsigned int t1, t2, fastest;
unsigned int timeb1v, timeb2v, timeb4v, timeb1s, timeb2s, timeb4s;
unsigned int timew1v, timew2v, timew4v, timew1s, timew2s, timew4s;
unsigned int timed1v, timed2v, timed4v, timed1s, timed2s, timed4s;
gr_init( 0 );
timer_init( 0, NULL );
TempBuffer1 = (unsigned char *)(((unsigned int)TempBufferX+0xF) & 0xFFFFFFF0);
System4 = (unsigned char *)(((unsigned int)TempBuffer2+0xF) & 0xFFFFFFF0);
System2 = (unsigned char *)((unsigned int)System4 + 2);
System1 = (unsigned char *)((unsigned int)System4 + 1);
Video4 = (unsigned char *)0xA0000;
Video2 = (unsigned char *)0xA0002;
Video1 = (unsigned char *)0xA0001;
t1 = timer_get_microseconds();
gr_linear_movsb(TempBuffer1, Video1, 320*200);
t2 = timer_get_microseconds();
t1 = timer_get_microseconds();
gr_linear_movsb(TempBuffer1, Video1, 320*200);
t2 = timer_get_microseconds();
fastest = t2-t1;
if ((t2-t1) < fastest) fastest = t2-t1;
timeb1v = t2 - t1;
t1 = timer_get_microseconds();
gr_linear_movsb(TempBuffer1, Video2, 320*200);
t2 = timer_get_microseconds();
t1 = timer_get_microseconds();
gr_linear_movsb(TempBuffer1, Video2, 320*200);
t2 = timer_get_microseconds();
if ((t2-t1) < fastest) fastest = t2-t1;
timeb2v = t2 - t1;
t1 = timer_get_microseconds();
gr_linear_movsb(TempBuffer1, Video4, 320*200);
t2 = timer_get_microseconds();
t1 = timer_get_microseconds();
gr_linear_movsb(TempBuffer1, Video4, 320*200);
t2 = timer_get_microseconds();
if ((t2-t1) < fastest) fastest = t2-t1;
timeb4v = t2 - t1;
t1 = timer_get_microseconds();
gr_linear_movsb(TempBuffer1, System1, 320*200);
t2 = timer_get_microseconds();
t1 = timer_get_microseconds();
gr_linear_movsb(TempBuffer1, System1, 320*200);
t2 = timer_get_microseconds();
if ((t2-t1) < fastest) fastest = t2-t1;
timeb1s = t2 - t1;
t1 = timer_get_microseconds();
gr_linear_movsb(TempBuffer1, System2, 320*200);
t2 = timer_get_microseconds();
t1 = timer_get_microseconds();
gr_linear_movsb(TempBuffer1, System2, 320*200);
t2 = timer_get_microseconds();
if ((t2-t1) < fastest) fastest = t2-t1;
timeb2s = t2 - t1;
t1 = timer_get_microseconds();
gr_linear_movsb(TempBuffer1, System4, 320*200);
t2 = timer_get_microseconds();
t1 = timer_get_microseconds();
gr_linear_movsb(TempBuffer1, System4, 320*200);
t2 = timer_get_microseconds();
if ((t2-t1) < fastest) fastest = t2-t1;
timeb4s = t2 - t1;
t1 = timer_get_microseconds();
gr_linear_movsw(TempBuffer1, Video1, 320*200);
t2 = timer_get_microseconds();
t1 = timer_get_microseconds();
gr_linear_movsw(TempBuffer1, Video1, 320*200);
t2 = timer_get_microseconds();
if ((t2-t1) < fastest) fastest = t2-t1;
timew1v = t2 - t1;
t1 = timer_get_microseconds();
gr_linear_movsw(TempBuffer1, Video2, 320*200);
t2 = timer_get_microseconds();
t1 = timer_get_microseconds();
gr_linear_movsw(TempBuffer1, Video2, 320*200);
t2 = timer_get_microseconds();
if ((t2-t1) < fastest) fastest = t2-t1;
timew2v = t2 - t1;
t1 = timer_get_microseconds();
gr_linear_movsw(TempBuffer1, Video4, 320*200);
t2 = timer_get_microseconds();
t1 = timer_get_microseconds();
gr_linear_movsw(TempBuffer1, Video4, 320*200);
t2 = timer_get_microseconds();
if ((t2-t1) < fastest) fastest = t2-t1;
timew4v = t2 - t1;
t1 = timer_get_microseconds();
gr_linear_movsw(TempBuffer1, System1, 320*200);
t2 = timer_get_microseconds();
t1 = timer_get_microseconds();
gr_linear_movsw(TempBuffer1, System1, 320*200);
t2 = timer_get_microseconds();
if ((t2-t1) < fastest) fastest = t2-t1;
timew1s = t2 - t1;
t1 = timer_get_microseconds();
gr_linear_movsw(TempBuffer1, System2, 320*200);
t2 = timer_get_microseconds();
t1 = timer_get_microseconds();
gr_linear_movsw(TempBuffer1, System2, 320*200);
t2 = timer_get_microseconds();
if ((t2-t1) < fastest) fastest = t2-t1;
timew2s = t2 - t1;
t1 = timer_get_microseconds();
gr_linear_movsw(TempBuffer1, System4, 320*200);
t2 = timer_get_microseconds();
t1 = timer_get_microseconds();
gr_linear_movsw(TempBuffer1, System4, 320*200);
t2 = timer_get_microseconds();
if ((t2-t1) < fastest) fastest = t2-t1;
timew4s = t2 - t1;
t1 = timer_get_microseconds();
gr_linear_movsd(TempBuffer1, Video1, 320*200);
t2 = timer_get_microseconds();
t1 = timer_get_microseconds();
gr_linear_movsd(TempBuffer1, Video1, 320*200);
t2 = timer_get_microseconds();
if ((t2-t1) < fastest) fastest = t2-t1;
timed1v = t2 - t1;
t1 = timer_get_microseconds();
gr_linear_movsd(TempBuffer1, Video2, 320*200);
t2 = timer_get_microseconds();
t1 = timer_get_microseconds();
gr_linear_movsd(TempBuffer1, Video2, 320*200);
t2 = timer_get_microseconds();
if ((t2-t1) < fastest) fastest = t2-t1;
timed2v = t2 - t1;
t1 = timer_get_microseconds();
gr_linear_movsd(TempBuffer1, Video4, 320*200);
t2 = timer_get_microseconds();
t1 = timer_get_microseconds();
gr_linear_movsd(TempBuffer1, Video4, 320*200);
t2 = timer_get_microseconds();
if ((t2-t1) < fastest) fastest = t2-t1;
timed4v = t2 - t1;
t1 = timer_get_microseconds();
gr_linear_movsd(TempBuffer1, System1, 320*200);
t2 = timer_get_microseconds();
t1 = timer_get_microseconds();
gr_linear_movsd(TempBuffer1, System1, 320*200);
t2 = timer_get_microseconds();
if ((t2-t1) < fastest) fastest = t2-t1;
timed1s = t2 - t1;
t1 = timer_get_microseconds();
gr_linear_movsd(TempBuffer1, System2, 320*200);
t2 = timer_get_microseconds();
t1 = timer_get_microseconds();
gr_linear_movsd(TempBuffer1, System2, 320*200);
t2 = timer_get_microseconds();
if ((t2-t1) < fastest) fastest = t2-t1;
timed2s = t2 - t1;
t1 = timer_get_microseconds();
gr_linear_movsd(TempBuffer1, System4, 320*200);
t2 = timer_get_microseconds();
t1 = timer_get_microseconds();
gr_linear_movsd(TempBuffer1, System4, 320*200);
t2 = timer_get_microseconds();
if ((t2-t1) < fastest) fastest = t2-t1;
timed4s = t2 - t1;
timer_close();
gr_close();
printf( "Relative memory move speeds: \n\n" );
printf( " Vid1 Vid2 Vid4 Sys1 Sys2 Sys4\n" );
printf( "REP MOVSB: %#2.2f %#2.2f %#2.2f %#2.2f %#2.2f %#2.2f\n", RelTime(timeb1v),RelTime(timeb2v),RelTime(timeb4v), RelTime(timeb1s),RelTime(timeb2s),RelTime(timeb4s) );
printf( "REP MOVSW: %#2.2f %#2.2f %#2.2f %#2.2f %#2.2f %#2.2f\n", RelTime(timew1v),RelTime(timew2v),RelTime(timew4v), RelTime(timew1s),RelTime(timew2s),RelTime(timew4s) );
printf( "REP MOVSD: %#2.2f %#2.2f %#2.2f %#2.2f %#2.2f %#2.2f\n", RelTime(timed1v),RelTime(timed2v),RelTime(timed4v), RelTime(timed1s),RelTime(timed2s),RelTime(timed4s) );
printf( "\nA 1.00 corresponds to %d microseconds to move 320x200 unsigned chars.\n", fastest );
return;
}
static int mve_do_timer_wait(void)
{
if (!timer_started) {
return 0;
}
#ifdef SCP_UNIX
int nsec = 0;
struct timespec ts, tsRem;
struct timeval tv;
gettimeofday(&tv, NULL);
if (tv.tv_sec > timer_expire.tv_sec) {
goto end;
}
if ( (tv.tv_sec == timer_expire.tv_sec) && (tv.tv_usec >= timer_expire.tv_usec) ) {
goto end;
}
ts.tv_sec = timer_expire.tv_sec - tv.tv_sec;
ts.tv_nsec = 1000 * (timer_expire.tv_usec - tv.tv_usec);
if (ts.tv_nsec < 0) {
ts.tv_nsec += 1000000000UL;
--ts.tv_sec;
}
if ( (nanosleep(&ts, &tsRem) == -1) && (errno == EINTR) ) {
// so we got an error that was a signal interupt, try to sleep again with remainder of time
if ( (nanosleep(&tsRem, NULL) == -1) && (errno == EINTR) ) {
mprintf(("MVE: Timer error! Aborting movie playback!\n"));
return 1;
}
}
end:
timer_expire.tv_usec += micro_frame_delay;
if (timer_expire.tv_usec > 1000000) {
nsec = timer_expire.tv_usec / 1000000;
timer_expire.tv_sec += nsec;
timer_expire.tv_usec -= nsec * 1000000;
}
#else
int tv, ts, ts2;
tv = timer_get_microseconds();
if (tv > timer_expire) {
goto end;
}
ts = timer_expire - tv;
ts2 = ts/1000;
Sleep(ts2);
end:
timer_expire += micro_frame_delay;
#endif
return 0;
}
float RocketSystemInterface::GetElapsedTime() { return timer_get_microseconds() / 1000000.f; }
/**
* 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_json_profiling)
{
std::lock_guard<std::mutex> guard(json_mutex);
tracing_data data;
data.name = name;
data.pid = get_pid();
data.tid = get_tid();
data.enter = true;
data.time = timer_get_nanoseconds();
if (do_gpu_queries) {
data.gpu_query = get_query_object();
gr_query_value(data.gpu_query, QueryType::Timestamp);
} else {
data.gpu_query = -1;
}
current_frame_data.push_back(data);
}
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_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_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_json_profiling)
{
std::lock_guard<std::mutex> guard(json_mutex);
tracing_data data;
data.name = name;
data.pid = get_pid();
data.tid = get_tid();
data.enter = false;
data.time = timer_get_nanoseconds();
if (do_gpu_queries) {
data.gpu_query = get_query_object();
gr_query_value(data.gpu_query, QueryType::Timestamp);
} else {
data.gpu_query = -1;
}
current_frame_data.push_back(data);
}
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;
std::uint64_t end_time = timer_get_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);
}
}
}
}
