[4.0] Fix block time reporting log statement

[heifner]

Fix issue with the tracking of block idle time.
Add producer name to the block time log statement.
Note: time logging trxs is now included in the success/fail time.

 Block #321409127 eosasia11111 trx idle: 253403us out of 340621us, success: 11, 11380us, fail: 10, 74407us, transient: 0, 0us, other: 1431us

Resolves #1360
Resolves #1417

[greg7mdp]

In this location, I think we do add_idle_time twice for the same time interval if we get an exception.

I think it would be more logical, everytime we effectively do the equivalent of:

_time_tracker.add_idle_time( fc::time_point::now() - self->_idle_trx_time);

We should immediately afterwards do: self->_idle_trx_time = fc::time_point::now();

This way we can ensure we don't count the same interval twice as idle.

And these two statements should be in a producer_plugin_impl() member function.

[greg7mdp]

Also _idle_trx_time is a bad name as it implies a duration, not a time stamp.

Maybe _unaccounted_idling_tstamp would be better, as it is the timestamp when we started being idle, and not accounted in time_tracker.

[greg7mdp]

I think a better design would be for the time tracker to hold the _unaccounted_timestamp and have a single api like:

class block_time_tracker
{
   enum class time_usage { idle, success, fail, last };

    void add_time(time_usage u)
    {
        auto now = fc::time_point::now();
        _time[static_cast<int>(u)] += now - _unaccounted_tstamp;
        _unaccounted_tstamp = now;
    }

   std::array<fc::microseconds, static_cast<int>(time_usage::last)> _time;
};

[heifner]

In this location, I think we do add_idle_time twice for the same time interval if we get an exception.

No, the only exception here (outside alloc exceptions which we can ignore since those are program exit) is via the future.get() as
process_incoming_transaction_async() does not throw. So the idle time is only set once.

[heifner]

We should immediately afterwards do: self->_idle_trx_time = fc::time_point::now();

The idle time does not start from there. It starts at the end of processing. Adding it here just makes it less likely you notice the logic is wrong.

[heifner]

Also _idle_trx_time is a bad name as it implies a duration, not a time stamp.

Interesting. I guess I have always thought of the term timestamp (tstamp) as more of an unix epoch term or as an implementation detail. A duration I would expect to be expressed as elapsed or similar. Maybe _idle_trx_timepoint ?

[heifner]

I think a better design would be for the time tracker to hold the _unaccounted_timestamp and have a single api like:

class block_time_tracker
{
   enum class time_usage { idle, success, fail, last };

    void add_time(time_usage u)
    {
        auto now = fc::time_point::now();
        _time[static_cast<int>(u)] += now - _unaccounted_tstamp;
        _unaccounted_tstamp = now;
    }

   std::array<fc::microseconds, static_cast<int>(time_usage::last)> _time;
};

A bit of Deja Vu on this. Seems like we had a similar discussion already. I'll see if I can clean up the current impl some.

[greg7mdp]

No, the only exception here (outside alloc exceptions which we can ignore since those are program exit) is via the future.get() as process_incoming_transaction_async() does not throw. So the idle time is only set once.

I'm not following. Either we can't have exceptions (in which case we can remove the try/catch block and the exception handler), or we can have exceptions (and when we do we will call add_idle_time twice with the same parameters). What am I missing?

[greg7mdp]

We should immediately afterwards do: self->_idle_trx_time = fc::time_point::now();

The idle time does not start from there. It starts at the end of processing. Adding it here just makes it less likely you notice the logic is wrong.

Yes, but when we call add_idle_time we add the interval [end of processing, now] to the accounted idle time. We should make sure that next time we call add_idle_time we don't take the same interval into account again.

[greg7mdp]

A bit of Deja Vu on this. Seems like we had a similar discussion already. I'll see if I can clean up the current impl some.

haha I already forgot all about it! You have a better memory than I do (not a high bar :-).
I'm just finding it hard to convince myself that we do update the idle time correctly from looking at the code, and I always try to figure out a way to make the code more obviously correct.

[heifner]

No, the only exception here (outside alloc exceptions which we can ignore since those are program exit) is via the future.get() as process_incoming_transaction_async() does not throw. So the idle time is only set once.

I'm not following. Either we can't have exceptions (in which case we can remove the try/catch block and the exception handler), or we can have exceptions (and when we do we will call add_idle_time twice with the same parameters). What am I missing?

The main reason the try-catch is here is for the future.get(). This can throw if signature validation fails.
The other reason is if process_incoming_transaction_async() throws a guard_exception which means app.quit() has been called and the program will soon exit, but we would not want an unhandled exception on the _thread_pool executor. Although, with recent changes to the named_thread_pool to handle uncaught exceptions on the executor we could likely get away with just a try-catch around the future.get(). But it is still nice that we call next in that corner case so that an API trx gets the reason for the failure.

[greg7mdp]

The main reason the try-catch is here is for the future.get(). This can throw if signature validation fails.

So if that happens, we'll call add_idle_time() twice with the same parameters, right?

[greg7mdp]

Interesting. I guess I have always thought of the term timestamp (tstamp) as more of an unix epoch term or as an implementation detail. A duration I would expect to be expressed as elapsed or similar. Maybe _idle_trx_timepoint ?

Yes, it is used in unix, but I was more thinking of the generic definition. But I'm fine with timepoint as well.

However, because we do update this timepoint, it is not necessarily the point we became idle, but really the point at which we last accounted for idle time (and updated the variable). That's what I was trying to convey with unaccounted, but maybe too much of a mouthful.

[heifner]

The main reason the try-catch is here is for the future.get(). This can throw if signature validation fails.

So if that happens, we'll call add_idle_time() twice with the same parameters, right?

I think I finally see what you are saying. Thanks! No idea why that add_idle_time call is in the exception_handler there is no idle time here. I'll remove it.

[heifner]

@greg7mdp Refactored to use RAII for a simpler interface.

[greg7mdp]

Nice changes.
I'd prefer with my suggestions below, so that everytime we add a time interval to success/fail/idle time, we also reset the last_trx_time_point

[greg7mdp]

Suggested change

	break; // just reset timer which happens below
	}
	_block_time_tracker.start_idle_time();
	_block_time_tracker.start_idle_time(); // just reset timer
	break;
	}

[greg7mdp]

Should we count exhausted transactions as successful?

[heifner]

They didn't fail, so don't want to count them as failed. We could count as other, but other is suppose to be time not spent evaluating trxs. We could add a whole new category, but that seems like it would just muddy the water. I think success is the best option. Time we spent successfully executing transactions; which is true.

[greg7mdp]

Hum, I wonder if it shouldn't be add_idle_time, with the change I mentioned before in add_idle_time resetting last_trx_time_point = now;

[heifner]

I don't understand; there is no idle time to add.

[greg7mdp]

OK, I see that start_idle_time(); does:

last_trx_time_point = now;

So assuming that now != last_trx_time_point, what was the time spent between last_trx_time_point and now used for?

[heifner]

It was used for start block which includes potentially many trx processing.

[greg7mdp]

Actually, we should probably call start_idle_time() only in ~trx_time_tracker() { (where we skip time to be accounted as other), and only call add_idle_time() elsewhere.

[greg7mdp]

We create a trx_time_tracker only when we start processing a transaction, right? So could it do add_other_time in its constructor?

[greg7mdp]

BTW I really like the RAII implementation!

[heifner]

We create a trx_time_tracker only when we start processing a transaction, right? So could it do add_other_time in its constructor?

But then you are just back to what it does now except you explicitly track the value instead of just calculate it.

[greg7mdp]

Hum, it is kind of true, especially with the current version of the code which increases the time_point every time we add a duration.
But still, if we track the "other" value explicitly, we can verify that the sum of all accounted times is the elapsed time, which may be not true if we were to create trx_time_tracker objects on more than one thread for example.

[heifner]

Added explicit tracking of other. Also added a pause/unpause for when in read-window as it didn't seem correct to call that "other" time.

[greg7mdp]

Nice! I think the code is easier to follow now.

[linh2931]

Not for this PR. We report timing only in debug logging, but we track timing no matter whether logging is enabled or not. Not sure how much time is spent on tracking in non-debugging mode.

[heifner]

Not for this PR. We report timing only in debug logging, but we track timing no matter whether logging is enabled or not. Not sure how much time is spent on tracking in non-debugging mode.

I wonder if this shouldn't be info level logging.