Lorre: "Processing latest Tezos fee data" for a long time

[ghost]

Hi,

I use Conseil with tezos on Carthagenet. I run Lorre (2020-july-release-24 version) like this:

java -Dconfig.file=lorre-carthagenet.conf -jar conseil-lorre.jar tezos carthagenet

Lorre config:

platforms {
  tezos {
    carthagenet {
      node {
        protocol: "http",
        hostname: "*************"
        port: ********
        pathPrefix: ""
      }
    }
  }
}

lorre {

  requestAwaitTime: 120 s
  GETResponseEntityTimeout: 90s
  POSTResponseEntityTimeout: 1s

  sleepInterval: 5 s
  bootupRetryInterval: 10 s
  bootupConnectionCheckTimeout: 10 s
  feeUpdateInterval: 20
  numberOfFeesAveraged: 1000
  depth: newest
  chainEvents: []
  blockRightsFetching: {
    initDelay: 2 minutes
    interval: 60 minutes
    cyclesToFetch: 5
    cycleSize: 4096
    fetchSize: 200
    updateSize: 16
  }
  
  batchedFetches {
    accountConcurrencyLevel: 5
    blockOperationsConcurrencyLevel: 10
    blockPageSize: 500
    blockPageProcessingTimeout: 1 hour
    accountPageProcessingTimeout: 15 minutes
    delegatePageProcessingTimeout: 15 minutes
  }

  db {
    dataSourceClass: "org.postgresql.ds.PGSimpleDataSource"
    properties {
      user: "*************"
      password: "***********"
      url: "jdbc:****************"
      reWriteBatchedInserts: true
    }
  }
  
}

It synchronises with tezos-node but it stops at the Processing latest Tezos fee data... step for a few minutes so the queries are not always up to date.
Log:

07:37:45.985 [lorre-tezos-indexer-akka.actor.default-dispatcher-54] INFO  t.c.c.i.tezos.TezosNodeOperator      - Fetching ballots
07:37:45.990 [lorre-tezos-indexer-akka.actor.default-dispatcher-54] INFO  t.c.c.i.t.TezosGovernanceOperations$ - Searching for governance data in voting period...
07:37:45.990 [lorre-tezos-indexer-akka.actor.default-dispatcher-54] INFO  t.c.c.i.t.TezosGovernanceOperations$ - There are no blocks related to testing vote and proposal vote periods.
07:37:46.008 [lorre-tezos-indexer-akka.actor.default-dispatcher-54] INFO  t.c.c.i.t.TezosDatabaseOperations$   - Writing 0 governance rows into database...
07:37:46.009 [lorre-tezos-indexer-akka.actor.default-dispatcher-54] INFO  t.c.c.i.t.p.AccountsProcessor        - Selecting all accounts left in the checkpoint table...
07:37:46.009 [lorre-tezos-indexer-akka.actor.default-dispatcher-54] INFO  t.c.c.i.t.TezosDatabaseOperations$   - Getting the latest accounts from checkpoints in the DB...
07:37:46.013 [lorre-tezos-indexer-akka.actor.default-dispatcher-54] INFO  t.c.c.i.t.p.AccountsProcessor        - No data to fetch from the accounts checkpoint
07:37:46.013 [lorre-tezos-indexer-akka.actor.default-dispatcher-54] INFO  t.c.c.i.t.processing.BakersProcessor - Selecting all bakers left in the checkpoint table...
07:37:46.013 [lorre-tezos-indexer-akka.actor.default-dispatcher-54] INFO  t.c.c.i.t.TezosDatabaseOperations$   - Getting the latest bakers from checkpoints in the DB...
07:37:46.016 [lorre-tezos-indexer-akka.actor.default-dispatcher-54] INFO  t.c.c.i.t.processing.BakersProcessor - No data to fetch from the bakers checkpoint
07:37:46.016 [lorre-tezos-indexer-akka.actor.default-dispatcher-54] INFO  t.c.c.i.tezos.TezosNodeOperator      - Fetching baking rights
07:37:46.017 [lorre-tezos-indexer-akka.actor.default-dispatcher-54] INFO  t.c.c.i.tezos.TezosNodeOperator      - Fetching endorsing rights
07:37:46.242 [lorre-tezos-indexer-akka.actor.default-dispatcher-39] INFO  t.c.c.i.t.TezosDatabaseOperations$   - Writing baking rights to the DB...
07:37:46.244 [lorre-tezos-indexer-akka.actor.default-dispatcher-39] INFO  t.c.c.i.t.TezosDatabaseOperations$   - Writing endorsing rights to the DB...
07:37:46.247 [lorre-tezos-indexer-akka.actor.default-dispatcher-39] INFO  t.c.c.indexer.tezos.TezosIndexer     - ================================== Progress Report ==================================
07:37:46.247 [lorre-tezos-indexer-akka.actor.default-dispatcher-39] INFO  t.c.c.indexer.tezos.TezosIndexer     - Completed processing 100.00% of total requested blocks
07:37:46.247 [lorre-tezos-indexer-akka.actor.default-dispatcher-39] INFO  t.c.c.indexer.tezos.TezosIndexer     - =====================================================================================
07:37:46.248 [lorre-tezos-indexer-akka.actor.default-dispatcher-29] INFO  t.c.c.i.tezos.TezosFeeOperations$    - Processing latest Tezos fee data...
07:43:00.561 [lorre-tezos-indexer-akka.actor.default-dispatcher-32] INFO  t.c.c.i.t.TezosDatabaseOperations$   - Writing fees to DB...
07:43:00.568 [lorre-tezos-indexer-akka.actor.default-dispatcher-32] INFO  t.c.c.i.tezos.TezosFeeOperations$    - Wrote 7 average fees to the database.
07:43:00.631 [lorre-tezos-indexer-akka.actor.default-dispatcher-32] INFO  RightsFetcher                        - Fetching future baking rights

As we can see, it took more than 5 minutes to get over this step.
Is there a way to make it smoother?

[ivanopagano]

Hello, @g574
This issue should be solved by the latest PR #907 which is on its way to get merged.

After that you can start using the latest master branch for "nightly" changes, or wait for the next official stable release.

[ivanopagano]

@g574 are you able to kindly check the latest master branch to verify if the issue is solved?

[ghost]

Hi @ivanopagano , thanks for the advise.
Unfortunately it does not work:

Exception in thread "main" org.postgresql.util.PSQLException: ERROR: column "invalidated_asof" does not exist
  Position: 49
        at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2440)
        at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2183)
        at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:308)
        at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:441)
        at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:365)
        at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:143)
        at org.postgresql.jdbc.PgPreparedStatement.execute(PgPreparedStatement.java:132)
        at com.zaxxer.hikari.pool.ProxyPreparedStatement.execute(ProxyPreparedStatement.java:44)
        at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.execute(HikariProxyPreparedStatement.java)
        at slick.jdbc.StatementInvoker.results(StatementInvoker.scala:39)
        at slick.jdbc.StatementInvoker.iteratorTo(StatementInvoker.scala:22)
        at slick.jdbc.Invoker.first(Invoker.scala:30)
        at slick.jdbc.Invoker.first$(Invoker.scala:29)
        at slick.jdbc.StatementInvoker.first(StatementInvoker.scala:16)
        at slick.jdbc.JdbcActionComponent$QueryActionExtensionMethodsImpl$$anon$3.run(JdbcActionComponent.scala:224)
        at slick.jdbc.JdbcActionComponent$SimpleJdbcProfileAction.run(JdbcActionComponent.scala:28)
        at slick.jdbc.JdbcActionComponent$SimpleJdbcProfileAction.run(JdbcActionComponent.scala:25)
        at slick.basic.BasicBackend$DatabaseDef$$anon$3.liftedTree1$1(BasicBackend.scala:276)
        at slick.basic.BasicBackend$DatabaseDef$$anon$3.run(BasicBackend.scala:276)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at java.base/java.lang.Thread.run(Thread.java:834)

Do I need to resynchronise the whole thing?

[ghost]

OK, I see the schema changed. I will need some time to resync then I can let you know the result.

[ivanopagano]

Thanks for being pro-active

[ghost]

Hi @ivanopagano, It is synchronised now and looks much smoother than before. Thanks for the help.
However, I face new challenges I didn't have before. They seem unrelated so I will open a new ticket for those.