Use CPU clock timeout for PVF jobs

[mrcnski]

PULL REQUEST

Overview

The idea behind this change is that the CPU clock is less affected by load than the wall clock.

We confirmed this empirically with an experiment.

The hope is that this reduces unnecessary disputes.

Changes

• The child worker now spawns a new separate thread, to monitor CPU time, whenever a job comes in.
  • The thread mostly sleeps and uses a strategy to wake up as little as possible.
  • If the job goes over the timeout the whole child process gets killed.
• The host still has a timeout for waiting for a response from the child, but it is 4x as lenient as before.
  • This is a wall clock timeout, since there is no good way to get a child's CPU time before the child process exits.
  • This is lenient because the wall clock can slow down up to a factor of 4 (tested on 32 threads of work on an 8-core machine).

TODO

• Add equivalent logic for PVF execution
• Add tests
• Small refactor of long match arm

Issues closed

Closes #4217

[vstakhov]

The idea behind this change is that the CPU clock is less affected by load than the wall clock.

Well, I'd say that it is more affected by load as this clock actually measures it's own process load. Hence, if a process is sleeping (e.g. waiting on epoll) it's clock of type CLOCK_PROCESS_CPUTIME_ID is not running as well. On the other hand, if the task is to measure the own load, this timer might be a good thing to check (but less portable than getrusage(RUSAGE_SELF)).

Wall clock is really affected by cpu load but it shouldn't be that significant unless we use coarse timers (and we should not do it in this case).

[mrcnski]

@vstakhov By "CPU clock is less affected by load than the wall clock" I mean the CPU clock of the process is less affected by load of the system (i.e. other processes). The load of the child process here is constant (preparing an artifact). We found that for a constant amount of work in the process, timing it with the cpu clock resulted in more consistent measurements than using the wall clock. Wall time varied up to a factor of 4 depending on system load, whereas measured CPU time varied by less than a factor of 2.

this timer might be a good thing to check (but less portable than getrusage(RUSAGE_SELF))

Do you mean as opposed to clock_gettime?

[s0me0ne-unkn0wn]

I love this one, it is not only about more precise measurements, in perspective it would allow us to enable more robust preparation and execution pipelines with better throughput, as CPU time does not depend on number of parallel workers as strongly as wall clock time.
My only concern is if it works equally well in different environments. Remember that we have to perform really weird checks and address some non-obvious problems in different environments. I think it should be evaluated in some way.

[vstakhov]

Do you mean as opposed to clock_gettime?

Yes, afair, the way to make it working in osx was not very pretty:

	thread_port_t thread = mach_thread_self();

	mach_msg_type_number_t count = THREAD_BASIC_INFO_COUNT;
	thread_basic_info_data_t info;
	if (thread_info (thread, THREAD_BASIC_INFO, (thread_info_t)&info, &count) != KERN_SUCCESS) {
		return -1;
	}

	res = info.user_time.seconds + info.system_time.seconds;
	res += ((double)(info.user_time.microseconds + info.system_time.microseconds)) / 1e6;
	mach_port_deallocate(mach_task_self(), thread);

Then I've switched to getrusage as it seems to be now in the basic POSIX spec.

Probably the support of CLOCK_PROCESS_CPUTIME_ID is now fixed in the more recent osx versions though.

[vstakhov]

By "CPU clock is less affected by load than the wall clock" I mean the CPU clock of the process is less affected by load of the system (i.e. other processes). The load of the child process here is constant (preparing an artifact). We found that for a constant amount of work in the process, timing it with the cpu clock resulted in more consistent measurements than using the wall clock.

That makes total sense, if the task is to measure own cpu load, then wall clock is not the best option due to preemption and other issues. CPU clock is also affected due to cache/tlb pollution but it is definitely a better option than a wall clock. However, if the evaluated code can wait/yeild somehow, then it might be possible to abuse this timer by performing very long sleep. On the other hand, this opportunity is covered by the fact that you also fire a wall clock timer in the parent process...

[eskimor]

That makes total sense, if the task is to measure own cpu load, then wall clock is not the best option due to preemption and other issues. CPU clock is also affected due to cache/tlb pollution but it is definitely a better option than a wall clock. However, if the evaluated code can wait/yeild somehow, then it might be possible to abuse this timer by performing very long sleep. On the other hand, this opportunity is covered by the fact that you also fire a wall clock timer in the parent process...

Yep, but as far as I know there should be no IO in the PVF execution. Everything should be in memory. The thing I am mostly worried about is swap or other ways the operating system might introduce disk fetches. Hence leaving a generous wall clock timeout just in case should be a good safe guard indeed.

Hmm, about sleep ... is this even supported @pepyakin ?

[mrcnski]

Then I've switched to getrusage as it seems to be now in the basic POSIX spec.

Probably the support of CLOCK_PROCESS_CPUTIME_ID is now fixed in the more recent osx versions though.

@vstakhov Looks like clock_gettime is also in the POSIX spec:
https://pubs.opengroup.org/onlinepubs/009696699/functions/clock_gettime.html

According to the docs for the cpu_time crate, MacOS has supported clock_gettime since 2016:
https://github.com/tailhook/cpu-time/blob/master/src/clock_gettime.rs#L60

Not sure how old of machines we want to support. It is simpler for me to use the cpu_time crate but I can switch to getrusage if you think that would be better.

[vstakhov]

Looks like clock_gettime is also in the POSIX spec:

It is in the realtime part that is technically an extension. But yes, it seems to be supported even by osx nowadays :)

It is simpler for me to use the cpu_time crate but I can switch to getrusage if you think that would be better.

I think this switch might be useful merely if there are any advantages of getrusage that are useful in our case. In general, getrusage provides more information than just cpu ticks. The question is whether there is any use case of that extra information. If not, I'd also stay with cpu_time as it covers the vast majority of the POSIX-ish OSes presented today.

[mrcnski]

I think this switch might be useful merely if there are any advantages of getrusage that are useful in our case. In general, getrusage provides more information than just cpu ticks. The question is whether there is any use case of that extra information. If not, I'd also stay with cpu_time as it covers the vast majority of the POSIX-ish OSes presented today.

Makes sense. I had a look, but there doesn't seem to be anything that could be useful:

struct rusage {
    struct timeval ru_utime; /* user CPU time used */
    struct timeval ru_stime; /* system CPU time used */
    long   ru_maxrss;        /* maximum resident set size */
    long   ru_ixrss;         /* integral shared memory size */
    long   ru_idrss;         /* integral unshared data size */
    long   ru_isrss;         /* integral unshared stack size */
    long   ru_minflt;        /* page reclaims (soft page faults) */
    long   ru_majflt;        /* page faults (hard page faults) */
    long   ru_nswap;         /* swaps */
    long   ru_inblock;       /* block input operations */
    long   ru_oublock;       /* block output operations */
    long   ru_msgsnd;        /* IPC messages sent */
    long   ru_msgrcv;        /* IPC messages received */
    long   ru_nsignals;      /* signals received */
    long   ru_nvcsw;         /* voluntary context switches */
    long   ru_nivcsw;        /* involuntary context switches */
};

[mrcnski]

At this point, I am just waiting for some quick feedback from @pepyakin or @slumber before finalizing this PR and moving it out of the draft stage.

[slumber]

2 more nits from me, other than that good to go

[slumber]

Why did you decide to move this code into prepare_artifact? To me it clearly belongs to some worker-related code, now it's unclear what prepare_artifact is responsible for (ditto for execute part).

[mrcnski]

Yeah, I wasn't sure about this change. In the execute part we were already getting the elapsed duration, which is a necessary part of the response returned from that function. And I wanted to put the lock flag as close as possible to the end of the execute operation, so I stuck it in the middle of that function kind of awkwardly. Then I figured I could do the same in the prepare part, for parity with the execute code and also to reduce indentation (I believe it saved 4 indent levels).

I considered alternatively adding another function wrapper around prepare_artifact called worker_prepare_job or something, which would have all this thread coordination logic in it. But I feel like it'd also be awkward to have this big chain of function calls.

I thought the present solution wasn't too bad, because prepare_artifact was not doing much previously -- it was basically just two function calls, to prevalidate and prepare. Felt like the least annoying option. It should probably be renamed to e.g. worker_prepare_job if we keep it like this.

[slumber]

I would've still went with this implementation, (personally) the readability was better despite indentation levels

[mrcnski]

Okay, I'll change it back. Thanks for the feedback.

[slumber]

This unreachable looks really scary and unnecessary, I would've went with a simple

// Monitor thread detected timeout and likely already terminated a process, nothing to do.
return

[eskimor]

We can also have a log or even a debug_assert.

[mrcnski]

Hmm, I don't see the point of logging a case that's unreachable, which we have a proof for. I would personally keep the unreachable and maybe just make it less verbose. We also can't just do an empty return here since worker_event_loop expects an io::Result<Never>>.

[slumber]

Yes, continue instead. Or

make it less verbose

would also work

[eskimor]

Well, unreachable code is more often reachable than one would expect - and if it were reached, you would like to know, as this would suggest a mistake in our reasoning of the code. While there is a proof, it is not very local. It is across function and even thread boundaries. This is a setup where a proof can relatively easily be invalidated by "remote" changes.

We are not in the Polkadot node here, but in a process that is expected to just have quit anyway - so it should not cause much harm. What would be the result of that unreachable hit - UnexpectedWorkerDeath? Given this, the unreachable should actually be fine.

[mrcnski]

Makes sense, removed the unreachable!.

[mrcnski]

Looks like the existing tests already cover timeouts, as well as successful execution within the timeout. I added some timing asserts where I could, but I wasn't sure how to test the CPU-time-specific changes, or if we need to.

[paritytech-cicd-pr]

The CI pipeline was cancelled due to failure one of the required jobs.
Job name: test-linux-stable
Logs: https://gitlab.parity.io/parity/mirrors/polkadot/-/jobs/2087671

[eskimor]

Nice work @m-cat !