Improvements to the tracing and logging in wasmer

[john-sharratt]

• Now using the fmt subscriber for improved formatting
• Using spans on all syscalls
• Added recorded fields on the spans instead trace and debug macros
• Adding timing on all syscall

[syrusakbary]

This looks great. I wished we did this earlier. Good work!

[theduke]

Very nice @john-sharratt !

One concern: since often the syscall args are in the spans now this has the potential to produce extremely noisy logs, we might want to move some of those back to just logging them in a first log message inside the syscall.

But we can just change that as we go along.

[john-sharratt]

Very nice @john-sharratt !

One concern: since often the syscall args are in the spans now this has the potential to produce extremely noisy logs, we might want to move some of those back to just logging them in a first log message inside the syscall.

But we can just change that as we go along.

the spans all have skip-all turned on by default - which means the number of fields have to be explicitly added and won't grow, but it might be an idea to add a feature flag for super noisy syscalls.

to be honest i think we should do the opposite though as I commended out the thread_local_get syscall debug and trace messages because they were so noisy... but then later (as in a few days ago) when I put the spans on i noticed there were millions of them now because of tokio going nuts with locals.

i think we should leave it noisy when in tracing mode, make it "useful" in debug level.... and optimize the code so that less syscalls are made. i mean the syscalls will be killing performance anyway

[theduke]

@john-sharratt small misunderstanding:

All syscalls should be instrumented, totally.

But we can chose between either including the fields in instrument(), which means they will be re-printed on each log message inside the created span, or just logging the values once with a manual trace!() which means they won't be in the span.

And I think we will mostly want to do the latter, except for very small stuff like maybe the fd.

[john-sharratt]

@john-sharratt small misunderstanding:

All syscalls should be instrumented, totally.

But we can chose between either including the fields in instrument(), which means they will be re-printed on each log message inside the created span, or just logging the values once with a manual trace!() which means they won't be in the span.

And I think we will mostly want to do the latter, except for very small stuff like maybe the fd.

Ah I understand - yeah that makes sense - we'll work towards that approach going forward