Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

txscript: Optimize trace logging. #2301

Merged
merged 1 commit into from
Jul 28, 2020

Conversation

davecgh
Copy link
Member

@davecgh davecgh commented Jul 26, 2020

After recent optimizations, the current next biggest offender of more allocations than would be expected revealed by profiling is due to the trace logging closures for the scripting engine execution.

Once upon a time, there was no way to check the current logging level with the logging infrastructure at the time and thus a logging closure was used to defer the fairly expensive construction of the trace logging information until it was actually invoked (meaning tracing is enabled).

However, those closures come at the cost of allocations, and since script execution is something that happens non-stop during normal operation, those allocations really add up, as the profiling shows.

As some point, the logging infrastructure was changed out, and it is now possible to determine the logging level, so this updates the code to take advantage of that and avoid the closures while still only performing the fairly expensive construction of trace logging information when tracing is enabled. In other words, with this change there is zero cost (other than the conditional check, of course) when tracing is not enabled.

Finally, this also removes the no longer necessary code related to creating the logging closures.

Relevant portion of the before profile:

github.com/decred/dcrd/txscript/v3.(*Engine).Execute
  Total:     6520930   13079822 (flat, cum) 19.23%
    588            .          .           	done := false 
    589            .          .           	for !done { 
    590      3309618    3309618           		log.Tracef("%v", newLogClosure(func() string { 
    591            .          .           			dis, err := vm.DisasmPC() 
    592            .          .           			if err != nil { 
    593            .          .           				return fmt.Sprintf("stepping - failed to disasm pc: %v", err) 
    594            .          .           			} 
    595            .          .           			return fmt.Sprintf("stepping %v", dis) 
    596            .          .           		})) 
    597            .          .            
    598            .    6558892           		done, err = vm.Step() 
    599            .          .           		if err != nil { 
    600            .          .           			return err 
    601            .          .           		} 
    602      3211312    3211312           		log.Tracef("%v", newLogClosure(func() string { 
    603            .          .           			var dstr, astr string 
    604            .          .            

Those logging sections are zero after this PR as expected.

@davecgh davecgh added this to the 1.6.0 milestone Jul 26, 2020
Copy link
Member

@dnldd dnldd left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nice, looks good.

After recent optimizations, the current next biggest offender of more
allocations than would be expected revealed by profiling is due to the
trace logging closures for the scripting engine execution.

Once upon a time, there was no way to check the current logging level
with the logging infrastructure at the time and thus a logging closure
was used to defer the fairly expensive construction of the trace logging
information until it was actually invoked (meaning tracing is enabled).

However, those closures come at the cost of allocations, and since
script execution is something that happens non-stop during normal
operation, those allocations really add up, as the profiling shows.

As some point, the logging infrastructure was changed out, and it is now
possible to determine the logging level, so this updates the code to
take advantage of that and avoid the closures while still only
performing the fairly expensive construction of trace logging
information when tracing is enabled. In other words, with this change
there is zero cost (other than the conditional check, of course) when
tracing is not enabled.

Finally, this also removes the no longer necessary code related to
creating the logging closures.
@davecgh davecgh merged commit f2839da into decred:master Jul 28, 2020
@davecgh davecgh deleted the txscript_no_log_closure branch July 28, 2020 21:51
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

3 participants