Merge pull request #556 from 0xPolygonHermez/fractasy_port_logs_impro…

…vements

Fractasy port logs improvements

src/config/config.cpp

@@ -300,6 +300,9 @@ void Config::load(json &config)
     // ECRecover
     ParseBool(config, "ECRecoverPrecalc", "ECRECOVER_PRECALC", ECRecoverPrecalc, false);
     ParseU64(config, "ECRecoverPrecalcNThreads", "ECRECOVER_PRECALC_N_THREADS", ECRecoverPrecalcNThreads, 16);
+
+    // Logs
+    ParseBool(config, "jsonLogs", "JSON_LOGS", jsonLogs, true);
 }
 
 void Config::print(void)

src/config/config.hpp

@@ -181,6 +181,8 @@ class Config
     bool ECRecoverPrecalc;
     uint64_t ECRecoverPrecalcNThreads;
 
+    bool jsonLogs;
+
     void load(json &config);
     bool generateProof(void) const { return runFileGenBatchProof || runFileGenAggregatedProof || runFileGenFinalProof || runAggregatorClient; }
     void print(void);

src/config/definitions.hpp

@@ -27,8 +27,8 @@
 //#define LOG_TIME_STATISTICS // If defined, generates main executor statistics for main operations
 //#define LOG_TIME_STATISTICS_STATEDB_REMOTE // If defined, generates remote statedb statistics
 //#define LOG_TIME_STATISTICS_STATEDB // If defined, generates statedb statistics
-#define LOG_TIME_STATISTICS_MAIN_EXECUTOR
-#define LOG_TIME_STATISTICS_STATE_MANAGER
+//#define LOG_TIME_STATISTICS_MAIN_EXECUTOR
+//#define LOG_TIME_STATISTICS_STATE_MANAGER
 //#define TIME_METRIC_TABLE
 //#define LOG_TXS
 //#define LOG_SERVICE

src/executor/executor.cpp

@@ -28,7 +28,7 @@ void Executor::process_batch (ProverRequest &proverRequest)
             }
             else*/
             {
-                zklog.info("Executor::process_batch() fork 1 native");
+                //zklog.info("Executor::process_batch() fork 1 native");
 
                 // Allocate committed polynomials for only 1 evaluation
                 void * pAddress = calloc(fork_1::CommitPols::numPols()*sizeof(Goldilocks::Element), 1);
@@ -57,7 +57,7 @@ void Executor::process_batch (ProverRequest &proverRequest)
             }
             else*/
             {
-                zklog.info("Executor::process_batch() fork 2 native");
+                //zklog.info("Executor::process_batch() fork 2 native");
 
                 // Allocate committed polynomials for only 1 evaluation
                 void * pAddress = calloc(fork_2::CommitPols::numPols()*sizeof(Goldilocks::Element), 1);
@@ -86,7 +86,7 @@ void Executor::process_batch (ProverRequest &proverRequest)
             }
             else*/
             {
-                zklog.info("Executor::process_batch() fork 3 native");
+                //zklog.info("Executor::process_batch() fork 3 native");
 
                 // Allocate committed polynomials for only 1 evaluation
                 void * pAddress = calloc(fork_3::CommitPols::numPols()*sizeof(Goldilocks::Element), 1);
@@ -111,12 +111,12 @@ void Executor::process_batch (ProverRequest &proverRequest)
         {
             if (config.useMainExecGenerated)
             {
-                zklog.info("Executor::process_batch() fork 4 generated");
+                //zklog.info("Executor::process_batch() fork 4 generated");
                 fork_4::main_exec_generated_fast(mainExecutor_fork_4, proverRequest);
             }
             else
             {
-                zklog.info("Executor::process_batch() fork 4 native");
+                //zklog.info("Executor::process_batch() fork 4 native");
 
                 // Allocate committed polynomials for only 1 evaluation
                 void * pAddress = calloc(fork_4::CommitPols::numPols()*sizeof(Goldilocks::Element), 1);
@@ -141,17 +141,17 @@ void Executor::process_batch (ProverRequest &proverRequest)
         {
             if (config.useMainExecC)
             {
-                zklog.info("Executor::process_batch() fork 5 C");
+                //zklog.info("Executor::process_batch() fork 5 C");
                 mainExecutorC_fork_5.execute(proverRequest);
             }
             else if (config.useMainExecGenerated)
             {
-                zklog.info("Executor::process_batch() fork 5 generated");
+                //zklog.info("Executor::process_batch() fork 5 generated");
                 fork_5::main_exec_generated_fast(mainExecutor_fork_5, proverRequest);
             }
             else
             {
-                zklog.info("Executor::process_batch() fork 5 native");
+                //zklog.info("Executor::process_batch() fork 5 native");
 
                 // Allocate committed polynomials for only 1 evaluation
                 void * pAddress = calloc(fork_5::CommitPols::numPols()*sizeof(Goldilocks::Element), 1);

src/hashdb/state_manager.cpp

@@ -499,7 +499,7 @@ zkresult StateManager::flush (const string &batchUUID, const string &_newStateRo
     gettimeofday(&t, NULL);
 #endif
 
-    TimerStart(STATE_MANAGER_FLUSH);
+    //TimerStart(STATE_MANAGER_FLUSH);
 
 #ifdef LOG_STATE_MANAGER
     zklog.info("StateManager::flush() batchUUID=" + batchUUID);
@@ -524,7 +524,7 @@ zkresult StateManager::flush (const string &batchUUID, const string &_newStateRo
             zklog.error("StateManager::flush() failed calling db.flush() result=" + zkresult2string(zkr));
         }
 
-        TimerStopAndLog(STATE_MANAGER_FLUSH);
+        //TimerStopAndLog(STATE_MANAGER_FLUSH);
 
 #ifdef LOG_TIME_STATISTICS_STATE_MANAGER
         //timeMetricStorage.add("flush UUID not found", TimeDiff(t));
@@ -702,7 +702,7 @@ zkresult StateManager::flush (const string &batchUUID, const string &_newStateRo
                         zklog.error("StateManager::flush() failed calling db.write() result=" + zkresult2string(zkr));
                         state.erase(it);
 
-                        TimerStopAndLog(STATE_MANAGER_FLUSH);
+                        //TimerStopAndLog(STATE_MANAGER_FLUSH);
 
 #ifdef LOG_TIME_STATISTICS_STATE_MANAGER
                         batchState.timeMetricStorage.add("flush error db.write", TimeDiff(t));
@@ -723,7 +723,7 @@ zkresult StateManager::flush (const string &batchUUID, const string &_newStateRo
                     zklog.error("StateManager::flush() failed calling string2fea() fea.size=" + to_string(fea.size()));
                     state.erase(it);
 
-                    TimerStopAndLog(STATE_MANAGER_FLUSH);
+                    //TimerStopAndLog(STATE_MANAGER_FLUSH);
 
 #ifdef LOG_TIME_STATISTICS_STATE_MANAGER
                     batchState.timeMetricStorage.add("flush error string2fea", TimeDiff(t));
@@ -745,7 +745,7 @@ zkresult StateManager::flush (const string &batchUUID, const string &_newStateRo
                     zklog.error("StateManager::flush() failed calling db.updateStateRoot() result=" + zkresult2string(zkr));
                     state.erase(it);
 
-                    TimerStopAndLog(STATE_MANAGER_FLUSH);
+                    //TimerStopAndLog(STATE_MANAGER_FLUSH);
 
 #ifdef LOG_TIME_STATISTICS_STATE_MANAGER
                     batchState.timeMetricStorage.add("flush error db.updateStateRoot", TimeDiff(t));
@@ -774,7 +774,7 @@ zkresult StateManager::flush (const string &batchUUID, const string &_newStateRo
 
     Unlock();
 
-    TimerStopAndLog(STATE_MANAGER_FLUSH);
+    //TimerStopAndLog(STATE_MANAGER_FLUSH);
 
     return zkr;
 }

src/main.cpp

@@ -310,7 +310,8 @@ int main(int argc, char **argv)
     file2json(pConfigFile, configJson);
     Config config;
     config.load(configJson);
-    zklog.setPrefix(config.proverID.substr(0, 7) + " "); // Set the logs prefix
+    zklog.setJsonLogs(config.jsonLogs);
+    zklog.setPID(config.proverID.substr(0, 7)); // Set the logs prefix
 
     // Print the zkProver version
     zklog.info("Version: " + string(ZKEVM_PROVER_VERSION));

src/prover/prover.cpp

@@ -355,11 +355,14 @@ ProverRequest *Prover::waitForRequestToComplete(const string &uuid, const uint64
 
 void Prover::processBatch(ProverRequest *pProverRequest)
 {
-    TimerStart(PROVER_PROCESS_BATCH);
+    //TimerStart(PROVER_PROCESS_BATCH);
     zkassert(pProverRequest != NULL);
     zkassert(pProverRequest->type == prt_processBatch);
 
-    zklog.info("Prover::processBatch() timestamp=" + pProverRequest->timestamp + " UUID=" + pProverRequest->uuid);
+    if (config.runAggregatorClient)
+    {
+        zklog.info("Prover::processBatch() timestamp=" + pProverRequest->timestamp + " UUID=" + pProverRequest->uuid);
+    }
 
     // Save input to <timestamp>.input.json, as provided by client
     if (config.saveInputToFile)
@@ -388,7 +391,7 @@ void Prover::processBatch(ProverRequest *pProverRequest)
         json2file(inputJsonEx, pProverRequest->inputDbFile());
     }
 
-    TimerStopAndLog(PROVER_PROCESS_BATCH);
+    //TimerStopAndLog(PROVER_PROCESS_BATCH);
 }
 
 void Prover::genBatchProof(ProverRequest *pProverRequest)

src/service/executor/executor_service.cpp

@@ -20,7 +20,9 @@ ::grpc::Status ExecutorServiceImpl::ProcessBatch(::grpc::ServerContext* context,
         return Status::CANCELLED;
     }
 
-    TimerStart(EXECUTOR_PROCESS_BATCH);
+    //TimerStart(EXECUTOR_PROCESS_BATCH);
+    struct timeval EXECUTOR_PROCESS_BATCH_start;
+    gettimeofday(&EXECUTOR_PROCESS_BATCH_start,NULL);
 
 #ifdef LOG_SERVICE
     zklog.info("ExecutorServiceImpl::ProcessBatch() got request:\n" + request->DebugString());
@@ -55,7 +57,7 @@ ::grpc::Status ExecutorServiceImpl::ProcessBatch(::grpc::ServerContext* context,
     {
         zklog.error("ExecutorServiceImpl::ProcessBatch() got oldStateRoot too long, size=" + to_string(request->old_state_root().size()));
         response->set_error(executor::v1::EXECUTOR_ERROR_INVALID_OLD_STATE_ROOT);
-        TimerStopAndLog(EXECUTOR_PROCESS_BATCH);
+        //TimerStopAndLog(EXECUTOR_PROCESS_BATCH);
         return Status::OK;
     }
     ba2scalar(proverRequest.input.publicInputsExtended.publicInputs.oldStateRoot, request->old_state_root());
@@ -65,7 +67,7 @@ ::grpc::Status ExecutorServiceImpl::ProcessBatch(::grpc::ServerContext* context,
     {
         zklog.error("ExecutorServiceImpl::ProcessBatch() got oldAccInputHash too long, size=" + to_string(request->old_acc_input_hash().size()));
         response->set_error(executor::v1::EXECUTOR_ERROR_INVALID_OLD_ACC_INPUT_HASH);
-        TimerStopAndLog(EXECUTOR_PROCESS_BATCH);
+        //TimerStopAndLog(EXECUTOR_PROCESS_BATCH);
         return Status::OK;
     }
     ba2scalar(proverRequest.input.publicInputsExtended.publicInputs.oldAccInputHash, request->old_acc_input_hash());
@@ -79,7 +81,7 @@ ::grpc::Status ExecutorServiceImpl::ProcessBatch(::grpc::ServerContext* context,
     {
         zklog.error("ExecutorServiceImpl::ProcessBatch() got chainID = 0");
         response->set_error(executor::v1::EXECUTOR_ERROR_INVALID_CHAIN_ID);
-        TimerStopAndLog(EXECUTOR_PROCESS_BATCH);
+        //TimerStopAndLog(EXECUTOR_PROCESS_BATCH);
         return Status::OK;
     }
 
@@ -91,7 +93,7 @@ ::grpc::Status ExecutorServiceImpl::ProcessBatch(::grpc::ServerContext* context,
     if (proverRequest.result != ZKR_SUCCESS)
     {
         response->set_error(zkresult2error(proverRequest.result));
-        TimerStopAndLog(EXECUTOR_PROCESS_BATCH);
+        //TimerStopAndLog(EXECUTOR_PROCESS_BATCH);
         return Status::OK;
     }
 
@@ -100,7 +102,7 @@ ::grpc::Status ExecutorServiceImpl::ProcessBatch(::grpc::ServerContext* context,
     {
         zklog.error("ExecutorServiceImpl::ProcessBatch() found batchL2Data.size()=" + to_string(request->batch_l2_data().size()) + " > MAX_BATCH_L2_DATA_SIZE=" + to_string(MAX_BATCH_L2_DATA_SIZE));
         response->set_error(executor::v1::EXECUTOR_ERROR_INVALID_BATCH_L2_DATA);
-        TimerStopAndLog(EXECUTOR_PROCESS_BATCH);
+        //TimerStopAndLog(EXECUTOR_PROCESS_BATCH);
         return Status::OK;
     }
     proverRequest.input.publicInputsExtended.publicInputs.batchL2Data = request->batch_l2_data();
@@ -110,7 +112,7 @@ ::grpc::Status ExecutorServiceImpl::ProcessBatch(::grpc::ServerContext* context,
     {
         zklog.error("ExecutorServiceImpl::ProcessBatch() got globalExitRoot too long, size=" + to_string(request->global_exit_root().size()));
         response->set_error(executor::v1::EXECUTOR_ERROR_INVALID_GLOBAL_EXIT_ROOT);
-        TimerStopAndLog(EXECUTOR_PROCESS_BATCH);
+        //TimerStopAndLog(EXECUTOR_PROCESS_BATCH);
         return Status::OK;
     }
     ba2scalar(proverRequest.input.publicInputsExtended.publicInputs.globalExitRoot, request->global_exit_root());
@@ -124,14 +126,14 @@ ::grpc::Status ExecutorServiceImpl::ProcessBatch(::grpc::ServerContext* context,
     {
         zklog.error("ExecutorServiceImpl::ProcessBatch() got sequencer address too long, size=" + to_string(auxString.size()));
         response->set_error(executor::v1::EXECUTOR_ERROR_INVALID_COINBASE);
-        TimerStopAndLog(EXECUTOR_PROCESS_BATCH);
+        //TimerStopAndLog(EXECUTOR_PROCESS_BATCH);
         return Status::OK;
     }
     if (!stringIsHex(auxString))
     {
         zklog.error("ExecutorServiceImpl::ProcessBatch() got sequencer address not hex, coinbase=" + auxString);
         response->set_error(executor::v1::EXECUTOR_ERROR_INVALID_COINBASE);
-        TimerStopAndLog(EXECUTOR_PROCESS_BATCH);
+        //TimerStopAndLog(EXECUTOR_PROCESS_BATCH);
         return Status::OK;
     }
     proverRequest.input.publicInputsExtended.publicInputs.sequencerAddr.set_str(auxString, 16);
@@ -144,14 +146,14 @@ ::grpc::Status ExecutorServiceImpl::ProcessBatch(::grpc::ServerContext* context,
     {
         zklog.error("ExecutorServiceImpl::ProcessBatch() got from too long, size=" + to_string(proverRequest.input.from.size()));
         response->set_error(executor::v1::EXECUTOR_ERROR_INVALID_FROM);
-        TimerStopAndLog(EXECUTOR_PROCESS_BATCH);
+        //TimerStopAndLog(EXECUTOR_PROCESS_BATCH);
         return Status::OK;
     }
     if (!stringIs0xHex(proverRequest.input.from))
     {
         zklog.error("ExecutorServiceImpl::ProcessBatch() got from not hex, size=" + proverRequest.input.from);
         response->set_error(executor::v1::EXECUTOR_ERROR_INVALID_FROM);
-        TimerStopAndLog(EXECUTOR_PROCESS_BATCH);
+        //TimerStopAndLog(EXECUTOR_PROCESS_BATCH);
         return Status::OK;
     }
 
@@ -219,14 +221,14 @@ ::grpc::Status ExecutorServiceImpl::ProcessBatch(::grpc::ServerContext* context,
         {
             zklog.error("ExecutorServiceImpl::ProcessBatch() got db key too long, size=" + to_string(key.size()));
             response->set_error(executor::v1::EXECUTOR_ERROR_INVALID_DB_KEY);
-            TimerStopAndLog(EXECUTOR_PROCESS_BATCH);
+            //TimerStopAndLog(EXECUTOR_PROCESS_BATCH);
             return Status::OK;
         }
         if (!stringIsHex(key))
         {
             zklog.error("ExecutorServiceImpl::ProcessBatch() got db key not hex, key=" + key);
             response->set_error(executor::v1::EXECUTOR_ERROR_INVALID_DB_KEY);
-            TimerStopAndLog(EXECUTOR_PROCESS_BATCH);
+            //TimerStopAndLog(EXECUTOR_PROCESS_BATCH);
             return Status::OK;
         }
         PrependZerosNoCopy(key, 64);
@@ -238,14 +240,14 @@ ::grpc::Status ExecutorServiceImpl::ProcessBatch(::grpc::ServerContext* context,
         {
             zklog.error("ExecutorServiceImpl::ProcessBatch() found db value not hex: " + concatenatedValues);
             response->set_error(executor::v1::EXECUTOR_ERROR_INVALID_DB_VALUE);
-            TimerStopAndLog(EXECUTOR_PROCESS_BATCH);
+            //TimerStopAndLog(EXECUTOR_PROCESS_BATCH);
             return Status::OK;
         }
         if (concatenatedValues.size()%16!=0)
         {
             zklog.error("ExecutorServiceImpl::ProcessBatch() found invalid db value size: " + to_string(concatenatedValues.size()));
             response->set_error(executor::v1::EXECUTOR_ERROR_INVALID_DB_VALUE);
-            TimerStopAndLog(EXECUTOR_PROCESS_BATCH);
+            //TimerStopAndLog(EXECUTOR_PROCESS_BATCH);
             return Status::OK;
         }
         for (uint64_t i=0; i<concatenatedValues.size(); i+=16)
@@ -275,14 +277,14 @@ ::grpc::Status ExecutorServiceImpl::ProcessBatch(::grpc::ServerContext* context,
         {
             zklog.error("ExecutorServiceImpl::ProcessBatch() got contracts key too long, size=" + to_string(key.size()));
             response->set_error(executor::v1::EXECUTOR_ERROR_INVALID_CONTRACTS_BYTECODE_KEY);
-            TimerStopAndLog(EXECUTOR_PROCESS_BATCH);
+            //TimerStopAndLog(EXECUTOR_PROCESS_BATCH);
             return Status::OK;
         }
         if (!stringIsHex(key))
         {
             zklog.error("ExecutorServiceImpl::ProcessBatch() got contracts key not hex, key=" + key);
             response->set_error(executor::v1::EXECUTOR_ERROR_INVALID_CONTRACTS_BYTECODE_KEY);
-            TimerStopAndLog(EXECUTOR_PROCESS_BATCH);
+            //TimerStopAndLog(EXECUTOR_PROCESS_BATCH);
             return Status::OK;
         }
         PrependZerosNoCopy(key, 64);
@@ -292,7 +294,7 @@ ::grpc::Status ExecutorServiceImpl::ProcessBatch(::grpc::ServerContext* context,
         {
             zklog.error("ExecutorServiceImpl::ProcessBatch() got contracts value not hex, value=" + itp->second);
             response->set_error(executor::v1::EXECUTOR_ERROR_INVALID_CONTRACTS_BYTECODE_VALUE);
-            TimerStopAndLog(EXECUTOR_PROCESS_BATCH);
+            //TimerStopAndLog(EXECUTOR_PROCESS_BATCH);
             return Status::OK;
         }
         vector<uint8_t> dbValue;
@@ -323,13 +325,15 @@ ::grpc::Status ExecutorServiceImpl::ProcessBatch(::grpc::ServerContext* context,
         " oldBatchNum=" + to_string(proverRequest.input.publicInputsExtended.publicInputs.oldBatchNum) +
         " chainId=" + to_string(proverRequest.input.publicInputsExtended.publicInputs.chainID) +
         " forkId=" + to_string(proverRequest.input.publicInputsExtended.publicInputs.forkID) +
+            (((proverRequest.input.publicInputsExtended.publicInputs.forkID >= 5) && config.useMainExecC) ? " C" :
+             ((proverRequest.input.publicInputsExtended.publicInputs.forkID >= 4) && config.useMainExecGenerated) ? " generated" : " native") +
         " globalExitRoot=" + proverRequest.input.publicInputsExtended.publicInputs.globalExitRoot.get_str(16) +
         " timestamp=" + to_string(proverRequest.input.publicInputsExtended.publicInputs.timestamp) +
-
         " from=" + proverRequest.input.from +
         " bUpdateMerkleTree=" + to_string(proverRequest.input.bUpdateMerkleTree) +
         " bNoCounters=" + to_string(proverRequest.input.bNoCounters) +
-        " traceConfig=" + proverRequest.input.traceConfig.toString());
+        " traceConfig=" + proverRequest.input.traceConfig.toString() +
+        " UUID=" + proverRequest.uuid);
 #endif
 
     if (config.logExecutorServerInputJson)
@@ -554,7 +558,9 @@ ::grpc::Status ExecutorServiceImpl::ProcessBatch(::grpc::ServerContext* context,
 
     //TimerStopAndLog(EXECUTOR_PROCESS_BATCH_BUILD_RESPONSE);
 
-    TimerStopAndLog(EXECUTOR_PROCESS_BATCH);
+    //TimerStopAndLog(EXECUTOR_PROCESS_BATCH);
+    struct timeval EXECUTOR_PROCESS_BATCH_stop;
+    gettimeofday(&EXECUTOR_PROCESS_BATCH_stop,NULL);
 
     if (config.saveResponseToFile)
     {

src/utils/utils.cpp

@@ -176,6 +176,15 @@ string getTimestamp(void)
     return buf;
 }
 
+string getTimestampWithPeriod(void)
+{
+    struct timeval tv;
+    gettimeofday(&tv, NULL);
+    char buf[256];
+    snprintf(buf, sizeof(buf), "%ld.%06ld", tv.tv_sec, tv.tv_usec);
+    return buf;
+}
+
 void getTimestampWithSlashes(string &timestamp, string &folder, string &file)
 {
     struct timeval tv;

src/utils/utils.hpp

@@ -34,6 +34,9 @@ void printCallStack (void);
 // Returns timestamp in UTC, e.g. "20230110_173200_128863"
 string getTimestamp(void);
 
+// Returns timestamp in UTC, e.g. "1653327845.128863"
+string getTimestampWithPeriod(void);
+
 // Returns timestamp in UTC with slashes up to the hour, e.g. "2023/01/10/17/3200_128863"
 void getTimestampWithSlashes(string &timestamp, string &folder, string &file);