Using printf to help trace ruby errors

[Al Hart]

After creating a script to trace ruby output to a file, I thought it might be a good idea to add a trace to every function call, with a line like this:

printf("FILE; %s; Line; %s\n", __FILE__, __LINE__) if $rps_show_traces

As in:

def test2(ii)
	printf("FILE; %s; Line; %s\n", __FILE__, __LINE__) if $rps_show_traces 
	i1 = 1
	i2 = i1+1
	return i2
end#def

if $rps_show_traces is true, I will get a trace message for every function like this:

(Does ruby already have anything like this to help trace function calls?)

FILE: /aa/test (2).rb: Line: 24

However if $rps_show_traces is not defined, or false, nothing will happen.

I wondered how much this would slow things down.

I also wondered it a if/end#if form would be significantly faster.

if $rps_show_traces ; printf("FILE; %s; Line; %s\n", __FILE__, __LINE__); end#if

So I created a test ruby to execute a function with the second form (if /end#if), the first form (if) and no trace statement at all.

Sure enough the if/end#if was faster, but after 5,000,000 function calls the time difference, and the time to include a line like this in the source at all, is insignificant.

if/end#if: elapsed 4.787 seconds
if only: elapsed 4.678 seconds (.10 seconds faster for 5,000,000 calls)
no trace: elapsed 4.279 seconds (.40 seconds faster for 5,000,000 calls)

So, although it would mess up the source code a bit, it would take no significant overhead to include a trace line after each function definition.

Here is the test routine if anyone wants to try it out.

def test1(ii)
	if $rps_show_traces ; printf("FILE; %s; Line; %s\n", __FILE__, __LINE__); end
	i1 = 1
	i2 = i1+1
	return i2
end#def

def test2(ii)
	printf("FILE; %s; Line; %s\n", __FILE__, __LINE__) if $rps_show_traces 
	i1 = 1
	i2 = i1+1
	return i2
end#def

def test3(ii)
	i1 = 1
	i2 = i1+1
	return i2
end#def

def do_all
	printf("FILE; %s; Line; %s\n", __FILE__, __LINE__)
	do_test1
	do_test2
	do_test3
end#def	

def do_test1
	start = Time.now
	ii = 0
	0.upto(5000000) { |ii| test1(ii) }
	etime = Time.now
	printf("if/end#if; elapsed %s seconds\n", etime - start)
	ii
end#def

def do_test2
	start = Time.now
	ii = 0
	0.upto(5000000) { |ii| test2(ii) }
	etime = Time.now
	printf("if only; elapsed %s seconds\n", etime - start)
	ii
end#def

def do_test3
	start = Time.now
	ii = 0
	0.upto(5000000) { |ii| test3(ii) }
	etime = Time.now
	printf("no trace; elapsed %s seconds\n", etime - start)
	ii
end#def

[Al Hart]

I was trying to get the function name in the trace as well.

It turns out that adding this line after every function definition may work well. It displays the rotuine name as well as the file and line number.

puts("TRACE: " + caller(1)[0].to_s) if $rps_show_traces