Bitshares-core: Get rid of fc::time_point::now()

Created on 17 Jan 2017 · 7Comments · Source: bitshares/bitshares-core

_From @theoreticalbts on August 30, 2015 0:26_

One of the problems with BTS 1.x design was that it was hard to test timing because everything did it differently. In Graphene, a single function graphene::time::now() is provided to interface to the real-time clock, with the idea that the clock can be mocked for testing. However, many places in the code do not use graphene::time::now().

libraries/chain/protocol/memo.cpp:         nonce = (fc::time_point::now().time_since_epoch().count()   &  0x00ffffffffffffff) | entropy;
libraries/app/application.cpp:      initial_state.initial_timestamp = time_point_sec(time_point::now().sec_since_epoch() /
libraries/plugins/delayed_node/delayed_node_plugin.cpp:   fc::schedule([this]{plugin_startup();}, fc::time_point::now() + fc::seconds(5));
libraries/wallet/wallet.cpp:                                                                          time_point_sec(time_point::now()),
libraries/wallet/wallet.cpp:         op.expiration = fc::time_point::now() + fc::seconds(timeout_sec);
libraries/wallet/wallet.cpp:   return my->_remote_hist->get_market_history( get_asset_id(symbol1), get_asset_id(symbol2), bucket, fc::time_point_sec(), fc::time_point::now() );
libraries/wallet/wallet.cpp:   result.date = fc::time_point::now();
libraries/wallet/include/graphene/wallet/wallet.hpp:                                                     time_point_sec expiration = time_point::now() + fc::minutes(1),

_Copied from original issue: cryptonomex/graphene#277_

Source

vikramrajkumar

All 7 comments

I was checking into this issue. First i added some logs to get time with the 2 methods and print it to the node output.

I added the logs to the get_block api function and then called it using the websocket. In the node output window i got:

2171706ms th_a       database_api.cpp:335          get_block            ] fc::time_point::now 2017-03-13T19:36:11
2171706ms th_a       database_api.cpp:336          get_block            ] graphene::time::now() 2017-03-13T19:36:11

Note that using the 2 methods the time output in the console is the same.

Now, checking in the entire code for graphene::time::now(), the issue from @theoreticalbts suggest to change everything to this(graphene::time::now()) to get time current:

root@NC-PH-1346-07:~/bitshares/bitshares-core#  grep -rnw '.' -e "graphene::time::now()"
./libraries/app/application.cpp:339:                  genesis.initial_timestamp = fc::time_point_sec( graphene::time::now() ) + genesis.initial_parameters.block_int
erval + _options->at("genesis-timestamp").as<uint32_t>();
./libraries/app/application.cpp:471:         graphene::time::now();
./libraries/app/application.cpp:541:         auto latency = graphene::time::now() - blk_msg.block.timestamp;
./libraries/app/application.cpp:913:      /** returns graphene::time::now() */
./libraries/app/application.cpp:916:         return graphene::time::now();
./libraries/plugins/witness/witness.cpp:54:   if( db.get_slot_at_time( graphene::time::now() ) > 200 )
./libraries/plugins/witness/witness.cpp:126:   graphene::time::now();
./libraries/plugins/witness/witness.cpp:154:   fc::time_point ntp_now = graphene::time::now();
./libraries/plugins/witness/witness.cpp:224:   fc::time_point now_fine = graphene::time::now();
root@NC-PH-1346-07:~/bitshares/bitshares-core#

As we can see this is used in only 2 files inside the code.

In the other hand the proposal to get rid of fc::time_point::now() is found in the following files:

root@NC-PH-1346-07:~/bitshares/bitshares-core# grep -rnw '.' -e "fc::time_point::now()"
./libraries/chain/db_update.cpp:56:         if( (fc::time_point::now() - b.timestamp) < fc::seconds(30) )
./libraries/chain/protocol/account.cpp:67:    if( fc::time_point::now() < fc::time_point(HARDFORK_385_TIME) )
./libraries/chain/protocol/memo.cpp:41:         nonce = (fc::time_point::now().time_since_epoch().count()   &  0x00ffffffffffffff) | entropy;
./libraries/chain/db_management.cpp:55:   auto start = fc::time_point::now();
./libraries/chain/db_management.cpp:98:   auto end = fc::time_point::now();
./libraries/time/time.cpp:78:      return fc::time_point::now() + fc::seconds( adjusted_time_sec );
./libraries/time/time.cpp:94:    return fc::time_point::now() + fc::seconds(adjusted_time_sec);
./libraries/time/time.cpp:106:  return *current_ntp_time - fc::time_point::now();
./libraries/app/application.cpp:600:         auto now = fc::time_point::now();
./libraries/app/database_api.cpp:1073:      auto now = fc::time_point_sec( fc::time_point::now() );
./libraries/app/database_api.cpp:1136:      auto now = fc::time_point_sec( fc::time_point::now() );
./libraries/app/database_api.cpp:1250:      start = fc::time_point_sec( fc::time_point::now() );
./libraries/plugins/witness/witness.cpp:155:   fc::time_point fc_now = fc::time_point::now();
./libraries/plugins/delayed_node/delayed_node_plugin.cpp:159:   fc::schedule([this]{connect();}, fc::time_point::now() + fc::seconds(5));
./libraries/net/peer_connection.cpp:51:        std::vector<char> packed_current_time = fc::raw::pack(fc::time_point::now());
./libraries/net/peer_connection.cpp:290:        _queued_messages.front()->transmission_start_time = fc::time_point::now();
./libraries/net/peer_connection.cpp:327:        _queued_messages.front()->transmission_finish_time = fc::time_point::now();
./libraries/net/peer_connection.cpp:389:        connection_terminated_time = fc::time_point::now();
./libraries/net/peer_connection.cpp:456:      return transaction_fetching_inhibited_until > fc::time_point::now();
./libraries/net/peer_connection.cpp:468:      fc::time_point_sec oldest_inventory_to_keep(fc::time_point::now() - fc::minutes(GRAPHENE_NET_MAX_INVENTORY_SIZE_IN_MIN
UTES));
./libraries/net/include/graphene/net/peer_connection.hpp:122:        queued_message(fc::time_point enqueue_time = fc::time_point::now()) :
./libraries/net/node.cpp:264:        timestamp(fc::time_point::now())
./libraries/net/node.cpp:342:          _call_requested_time(fc::time_point::now()),
./libraries/net/node.cpp:350:          fc::time_point end_time(fc::time_point::now());
./libraries/net/node.cpp:372:          _begin_execution_time = fc::time_point::now();
./libraries/net/node.cpp:376:          _execution_completed_time = fc::time_point::now();
./libraries/net/node.cpp:848:            updated_peer_record->last_seen_time = fc::time_point::now();
./libraries/net/node.cpp:934:                   (fc::time_point::now() - iter->last_connection_attempt_time) > delay_until_retry))
./libraries/net/node.cpp:959:              _retrigger_connect_loop_promise->wait_until( fc::time_point::now() + fc::seconds(GRAPHENE_PEER_DATABASE_RETRY_DELAY ) );
./libraries/net/node.cpp:1009:      _active_sync_requests.insert( active_sync_requests_map::value_type(item_to_request, fc::time_point::now() ) );
./libraries/net/node.cpp:1010:      peer->sync_items_requested_from_peer.insert( peer_connection::item_to_time_map_type::value_type(item_id_to_request, fc::time_poi
nt::now() ) );
./libraries/net/node.cpp:1022:        _active_sync_requests.insert( active_sync_requests_map::value_type(item_to_request, fc::time_point::now() ) );
./libraries/net/node.cpp:1024:        peer->sync_items_requested_from_peer.insert( peer_connection::item_to_time_map_type::value_type(item_id_to_request, fc::time_p
oint::now() ) );
./libraries/net/node.cpp:1121:        fc::time_point oldest_timestamp_to_fetch = fc::time_point::now() - fc::seconds(_recent_block_interval_in_seconds * GRAPHENE_NE
T_MESSAGE_CACHE_DURATION_IN_BLOCKS);
./libraries/net/node.cpp:1176:                  peer->items_requested_from_peer.insert(peer_connection::item_to_time_map_type::value_type(item_id_to_fetch, fc::time
_point::now()));
./libraries/net/node.cpp:1216:            time_until_retrigger = next_peer_unblocked_time - fc::time_point::now();
./libraries/net/node.cpp:1277:                peer->inventory_advertised_to_peer.insert(peer_connection::timestamped_item_id(item_to_advertise, fc::time_point::now(
)));
./libraries/net/node.cpp:1339:        fc::time_point handshaking_disconnect_threshold = fc::time_point::now() - fc::seconds(handshaking_timeout);
./libraries/net/node.cpp:1375:        fc::time_point active_disconnect_threshold = fc::time_point::now() - fc::seconds(active_disconnect_timeout);
./libraries/net/node.cpp:1376:        fc::time_point active_send_keepalive_threshold = fc::time_point::now() - fc::seconds(active_send_keepalive_timeout);
./libraries/net/node.cpp:1377:        fc::time_point active_ignored_request_threshold = fc::time_point::now() - active_ignored_request_timeout;
./libraries/net/node.cpp:1433:        fc::time_point closing_disconnect_threshold = fc::time_point::now() - fc::seconds(GRAPHENE_NET_PEER_DISCONNECT_TIMEOUT);
./libraries/net/node.cpp:1445:        fc::time_point failed_terminate_threshold = fc::time_point::now() - fc::seconds(failed_terminate_timeout_seconds);
./libraries/net/node.cpp:1484:                                                      ( "last_message_received_seconds_ago", (peer->get_last_message_received_time() -
 fc::time_point::now() ).count() / fc::seconds(1 ).count() )
./libraries/net/node.cpp:1485:                                                      ( "last_message_sent_seconds_ago", (peer->get_last_message_sent_time() - fc::tim
e_point::now() ).count() / fc::seconds(1 ).count() )
./libraries/net/node.cpp:1498:                                                                   fc::time_point::now() + fc::seconds(GRAPHENE_NET_PEER_HANDSHAKE_INA
CTIVITY_TIMEOUT / 2),
./libraries/net/node.cpp:1526:      fc::time_point_sec oldest_failed_ids_to_keep(fc::time_point::now() - fc::minutes(15));
./libraries/net/node.cpp:1533:                                                             fc::time_point::now() + fc::minutes(15),
./libraries/net/node.cpp:1563:      fc::time_point_sec current_time = fc::time_point::now();
./libraries/net/node.cpp:1579:                                                     fc::time_point::now() + fc::seconds(1),
./libraries/net/node.cpp:1589:                                                   fc::time_point::now() + fc::minutes(1),
./libraries/net/node.cpp:2103:      fc::time_point now = fc::time_point::now();
./libraries/net/node.cpp:2140:            updated_peer_record->last_connection_attempt_time = fc::time_point::now();
./libraries/net/node.cpp:2167:            updated_peer_record->last_seen_time = fc::time_point::now();
./libraries/net/node.cpp:2172:                                                    fc::time_point::now(),
./libraries/net/node.cpp:2192:        address.last_seen_time = fc::time_point_sec(fc::time_point::now());
./libraries/net/node.cpp:2429:        peer->item_ids_requested_from_peer = boost::make_tuple( blockchain_synopsis, fc::time_point::now() );
./libraries/net/node.cpp:2860:          originating_peer->inventory_peer_advertised_to_us.insert(peer_connection::timestamped_item_id(advertised_item_id, fc::time_p
oint::now()));
./libraries/net/node.cpp:2884:                                                            [](prioritized_item_id& item) { item.timestamp = fc::time_point::now(); })
;
./libraries/net/node.cpp:2955:            updated_peer_record->last_seen_time = fc::time_point::now();
./libraries/net/node.cpp:3215:      //fc::time_point start_time = fc::time_point::now();
./libraries/net/node.cpp:3321:      fc::time_point message_receive_time = fc::time_point::now();
./libraries/net/node.cpp:3342:          message_validated_time = fc::time_point::now();
./libraries/net/node.cpp:3523:      fc::time_point request_received_time(fc::time_point::now());
./libraries/net/node.cpp:3533:      fc::time_point reply_received_time = fc::time_point::now();
./libraries/net/node.cpp:3664:                  updated_peer_record.last_seen_time = fc::time_point::now();
./libraries/net/node.cpp:3732:      fc::time_point now = fc::time_point::now();
./libraries/net/node.cpp:3787:      fc::time_point message_receive_time = fc::time_point::now();
./libraries/net/node.cpp:3818:          message_validated_time = fc::time_point::now();
./libraries/net/node.cpp:3828:          _recently_failed_items.insert(peer_connection::timestamped_item_id(item_id(message_to_process.msg_type, message_hash ), fc::
time_point::now()));
./libraries/net/node.cpp:4182:          new_peer->connection_initiation_time = fc::time_point::now();
./libraries/net/node.cpp:4254:        updated_peer_record.last_connection_attempt_time = fc::time_point::now();;
./libraries/net/node.cpp:4275:        updated_peer_record.last_seen_time = fc::time_point::now();
./libraries/net/node.cpp:4421:                                                                                          fc::time_point::now() - fc::seconds(_peer_co
nnection_retry_timeout));
./libraries/net/node.cpp:4564:                                                                                      fc::time_point::now() - fc::seconds(_peer_connec
tion_retry_timeout));
./libraries/net/node.cpp:4574:      new_peer->connection_initiation_time = fc::time_point::now();
./libraries/net/node.cpp:4720:            updated_peer_record->last_seen_time = fc::time_point::now();
./libraries/net/node.cpp:4729:        peer_to_disconnect->connection_closed_time = fc::time_point::now();
./libraries/net/node.cpp:4884:      message_propagation_data propagation_data{fc::time_point::now(), fc::time_point::now(), _node_id};
./libraries/net/message_oriented_connection.cpp:148:      _connected_time = fc::time_point::now();
./libraries/net/message_oriented_connection.cpp:175:          _last_message_received_time = fc::time_point::now();
./libraries/net/message_oriented_connection.cpp:269:        _last_message_sent_time = fc::time_point::now();
./libraries/wallet/wallet.cpp:1947:         op.expiration = fc::time_point::now() + fc::seconds(timeout_sec);
./libraries/wallet/wallet.cpp:2528:         fc::time_point start = fc::time_point::now();
./libraries/wallet/wallet.cpp:2535:         fc::time_point end = fc::time_point::now();
./libraries/wallet/wallet.cpp:2539:         start = fc::time_point::now();
./libraries/wallet/wallet.cpp:2545:         end = fc::time_point::now();
./libraries/wallet/wallet.cpp:2549:         start = fc::time_point::now();
./libraries/wallet/wallet.cpp:2554:         end = fc::time_point::now();
./libraries/wallet/wallet.cpp:4279:   result.date = fc::time_point::now();
./tests/performance/performance_tests.cpp:47:   auto start = fc::time_point::now();
./tests/performance/performance_tests.cpp:50:   auto end = fc::time_point::now();
./tests/performance/performance_tests.cpp:60:   auto start = fc::time_point::now();
./tests/performance/performance_tests.cpp:66:   auto end = fc::time_point::now();
./tests/benchmarks/genesis_allocation.cpp:78:         fc::time_point start_time = fc::time_point::now();
./tests/benchmarks/genesis_allocation.cpp:80:         ilog("Closed database in ${t} milliseconds.", ("t", (fc::time_point::now() - start_time).count() / 1000));
./tests/benchmarks/genesis_allocation.cpp:85:         fc::time_point start_time = fc::time_point::now();
./tests/benchmarks/genesis_allocation.cpp:87:         ilog("Opened database in ${t} milliseconds.", ("t", (fc::time_point::now() - start_time).count() / 1000));
./tests/benchmarks/genesis_allocation.cpp:97:         start_time = fc::time_point::now();
./tests/benchmarks/genesis_allocation.cpp:110:              ("c", blocks_out)("t", (fc::time_point::now() - start_time).count() / 1000));
./tests/benchmarks/genesis_allocation.cpp:112:         start_time = fc::time_point::now();
./tests/benchmarks/genesis_allocation.cpp:114:         ilog("Closed database in ${t} milliseconds.", ("t", (fc::time_point::now() - start_time).count() / 1000));
./tests/benchmarks/genesis_allocation.cpp:119:         auto start_time = fc::time_point::now();
./tests/benchmarks/genesis_allocation.cpp:122:         ilog("Replayed database in ${t} milliseconds.", ("t", (fc::time_point::now() - start_time).count() / 1000));
root@NC-PH-1346-07:~/bitshares/bitshares-core#

As can be seen the "fc::time_point::now()" is a lot more used than "graphene::time::now()". If there is one that we should get rid of i think it should be easier if it is "graphene::time::now()". As the output is actually the same i will like to see some opinions if we should get rid of one or the other.

A sample of the timing test that it is being hard to implement due to the use of this 2 functions will be also good to have.

oxarbitrage on 13 Mar 2017

👍1

Graphene time (https://github.com/bitshares/bitshares-core/blob/master/libraries/time/time.cpp) is optionally simulated during testing and otherwise is NTP time, with a fallback to the system clock. fc time (https://github.com/bitshares/bitshares-fc/blob/master/src/time.cpp) is system clock time. Either one may be valid in a specific situation depending on the context.

vikramrajkumar on 13 Mar 2017

do you think we should get rid of any of the 2 ?

oxarbitrage on 13 Mar 2017

It appears that the simulated time mechanism is never actually used including during any testing. Conceivably we could remove it along with NTP time and use the system clock for everything, and add the requirement that to run BitShares your system clock needs to be synced externally.

I kind of prefer that simplification but this is low priority and I would say we leave it as-is for now.

vikramrajkumar on 14 Mar 2017

👍1

https://github.com/bitshares/bitshares-core/pull/247

As we are already here i made a pull request that replaces all the
graphene::time::now() with fc::time_point::now()in the 2 files where this is used(
libraries/app/application.cpp and libraries/plugins/witness/witness.cpp).

Code was compiled, started and accepted connections from a light wallet. All good, no difference with nodes that don't have the change.

oxarbitrage on 15 Mar 2017

Although I like the idea of having the option to simulate time, I would rather have all of the code be consistent with each other using either graphene::time::now() or fc::time_point::now().

Since it is low priority, I agree with the idea of replacing graphene::time::now() for now since it requires fewer changes and currently appears to yield identical results.

Later, if time testing would be helpful, we can go implement the opposite.