Bug #15634: TracePoint seems to be skipping some methods.

• Status: Closed
• Priority: Normal
• Assignee: -
• Target version: -
• ruby -v: 2.6.1
• Backport: 2.4: UNKNOWN, 2.5: UNKNOWN, 2.6: UNKNOWN
• Tags: tracepoint

[ioquatix (Samuel Williams)]

trace_point = TracePoint.new(:call, :return, :line, :c_call, :c_return, :b_call, :b_return) do |trace|
    puts [trace.path, trace.lineno].join(":")
end

trace_point.enable

values = {foo: 10}

def shell_escape(x)
    x
end

values.map{|key, value| [
    key.to_s.upcase,
    shell_escape(value) # TracePoint is never triggered for this line.
]}

[ioquatix (Samuel Williams)]

Here is more elaborate example:

#!/usr/bin/env ruby

trace_point = TracePoint.new(:call, :return, :line, :c_call, :c_return, :b_call, :b_return) do |trace|
    puts [trace.path, trace.lineno].join(":")
end

trace_point.enable

values = {foo: 10}

def shell_escape(x)
    x
end

values.map{|key, value| [
    key.to_s.upcase,
    shell_escape(value) # TracePoint is never triggered for this line.
]}

Here is output:

<internal:prelude>:137
<internal:prelude>:138
/private/var/folders/3x/tvygzl0s65520b6t4tzqbt980000gn/T/8efd0295-4252-4947-a870-2c636bf2e120:9
/private/var/folders/3x/tvygzl0s65520b6t4tzqbt980000gn/T/8efd0295-4252-4947-a870-2c636bf2e120:11
/private/var/folders/3x/tvygzl0s65520b6t4tzqbt980000gn/T/8efd0295-4252-4947-a870-2c636bf2e120:11
/private/var/folders/3x/tvygzl0s65520b6t4tzqbt980000gn/T/8efd0295-4252-4947-a870-2c636bf2e120:11
/private/var/folders/3x/tvygzl0s65520b6t4tzqbt980000gn/T/8efd0295-4252-4947-a870-2c636bf2e120:15
/private/var/folders/3x/tvygzl0s65520b6t4tzqbt980000gn/T/8efd0295-4252-4947-a870-2c636bf2e120:15
/private/var/folders/3x/tvygzl0s65520b6t4tzqbt980000gn/T/8efd0295-4252-4947-a870-2c636bf2e120:15
/private/var/folders/3x/tvygzl0s65520b6t4tzqbt980000gn/T/8efd0295-4252-4947-a870-2c636bf2e120:15
/private/var/folders/3x/tvygzl0s65520b6t4tzqbt980000gn/T/8efd0295-4252-4947-a870-2c636bf2e120:16
/private/var/folders/3x/tvygzl0s65520b6t4tzqbt980000gn/T/8efd0295-4252-4947-a870-2c636bf2e120:16
/private/var/folders/3x/tvygzl0s65520b6t4tzqbt980000gn/T/8efd0295-4252-4947-a870-2c636bf2e120:16
/private/var/folders/3x/tvygzl0s65520b6t4tzqbt980000gn/T/8efd0295-4252-4947-a870-2c636bf2e120:16
/private/var/folders/3x/tvygzl0s65520b6t4tzqbt980000gn/T/8efd0295-4252-4947-a870-2c636bf2e120:16
/private/var/folders/3x/tvygzl0s65520b6t4tzqbt980000gn/T/8efd0295-4252-4947-a870-2c636bf2e120:11
/private/var/folders/3x/tvygzl0s65520b6t4tzqbt980000gn/T/8efd0295-4252-4947-a870-2c636bf2e120:12
/private/var/folders/3x/tvygzl0s65520b6t4tzqbt980000gn/T/8efd0295-4252-4947-a870-2c636bf2e120:13
/private/var/folders/3x/tvygzl0s65520b6t4tzqbt980000gn/T/8efd0295-4252-4947-a870-2c636bf2e120:18
/private/var/folders/3x/tvygzl0s65520b6t4tzqbt980000gn/T/8efd0295-4252-4947-a870-2c636bf2e120:15
/private/var/folders/3x/tvygzl0s65520b6t4tzqbt980000gn/T/8efd0295-4252-4947-a870-2c636bf2e120:15

Line 17 (the one marked by comment) is never executed.

[jeremyevans0 (Jeremy Evans)]

The reason there is no event emitted for Line 17 in the example (#note-1) is there is no new expression/statement on that line. It is a continuation of the previous expression. I think we should adjust the documentation for the :line event to reflect the current behavior, and submitted a pull request for that: https://github.com/ruby/ruby/pull/4589.

The alternative would be emitting line events at many more places than we do now. For example, do we want 1, 3, or 5 line events for this:

[
  1,
  2,
  3
]

I think trying to increase the number of line events would require a lot of work for very little practical gain. In other words, the cost of doing so is much higher than the benefits.

[jeremyevans0 (Jeremy Evans)]

• Related to Bug #14889: TracePoint for :line never seems to trigger on argument list. Maybe by design? added

• Status changed from Open to Closed

Applied in changeset git|72a4e1d3bbbdfff71ec2c6b2ddb3b9323193cacd.

---

Tweak description of TracePoint :line event

"code" here is too ambiguous. TracePoint events only occur if there
is a new statement or expression on that line, not if the line
is a continuation of a previous statement or expression and there
is no new statement or expression on the line.

For example:

[
 foo,   # start of expression, line event
 bar    # continuation of expression, no line event
]

[
 foo,   # start of expression, line event
 (bar)  # new expression, line event
]

foo(    # start of expression, line event
  bar   # continuation of expression, no line event
)

foo(    # start of expression, line event
  (bar) # new expression, line event
)

Fixes [Bug #15634]

[ioquatix (Samuel Williams)]

I wouldn't say this bug is fixed. Adding documentation just clarifies the current behaviour but does not help resolve or improve on the original problem.

I would say, the line tracepoint is confusing at best, as one might expect it to trigger for each "line" of executable code. The implementation obviously skips some cases, but documenting the cases that it skips does not help me much to improve the coverage computation.

Maybe the problem is the naming of the tracepoint - maybe it should be called "statement" or "top_level_expression".

[jeremyevans0 (Jeremy Evans)]

ioquatix (Samuel Williams) wrote in #note-5:

I wouldn't say this bug is fixed. Adding documentation just clarifies the current behaviour but does not help resolve or improve on the original problem.

Well, it depends on whether you think the current behavior is a code bug or documentation bug. I don't think it is a code bug, because the code was not designed to give the behavior you want. Maybe that is a design flaw, but it's not a bug in the implementation. I agree with you that there is room for improvement in this area, but I think proposed improvements would be feature requests.

I would say, the line tracepoint is confusing at best, as one might expect it to trigger for each "line" of executable code. The implementation obviously skips some cases, but documenting the cases that it skips does not help me much to improve the coverage computation.

I agree that :line as a name is not completely accurate. With the example I gave in #note-2:

[
  1,
  2,
  3
]

You could reasonably assume either 3 or 5 :line events instead of the current 1.

Another issue I noticed with the :line coverage is the above example has the :line event as the first line, but if the array contains a non-literal, the :line event is on the second line.

Maybe the problem is the naming of the tracepoint - maybe it should be called "statement" or "top_level_expression".

The issue with either of those names is that it could be trigger multiple times on the same line, so it wouldn't be a replacement for the current :line event. I could see where they would be useful as additional events, though.