Inconsistency between time taken for write to db node to complete and the timing shown in the 'data-store-details.csv' log

Hello Everyone,

I have a query regarding the time of Write to Datastore operation reported in the log file "data_store_details.csv"
This log file breaks the total time for the write to DB query to execute in "Mean Prepare Time", "Mean Execute Time" and "Mean Transform time". Now, for one example - on one environment I am working on - the durations reported for these are 5ms, 16ms and 5ms respectively - for a total of 26ms of Mean Total time.

Now, I observed the time taken for the "Write to Datastore" node to complete in the process history of the process instance. It shows the time as 1.04 seconds. This indicates the Write to datastore node took 1.04 seconds to complete. However, from the log file - I see that the actual database operation took a total of 26ms.

So, why is there some...

OriginalPostID-265602

  Discussion posts and replies are publicly visible

  • ... time unaccounted for? Apparently, the Write to DB node should also have completed in around 26-30ms. But this is not the case. Similar observation was made for Write to Multiple DS node.

    I think the remaining time will be needed by Appian for things like logging the DB operation(which ideally would happen in async manner), adding it in process history of the process instance, assigning to the CDT variable the output of write to DB is saved into etc.
    Also, does the "Execute"/"Transform" time of a query include the network round-trip time?
    Obviously, Appian has to send the DB query to the server by first opening a connection(which is managed by Hibernate internally in Appian). If the network is slow or the database latency is more, I guess we can expect to see more time lag - and hence longer duration for the DB node to complete.

    Can anyone confirm if my assumption is correct? Whether this really is the case?
    Please note that we are using the Orac...
  • 0
    Certified Lead Developer
    @chetany i think process history holds overall time taken for this instance to get complete, rather than a particular node execution time, please correct me if i am wrong.

    Also can you please let us know, how exactly are trying to capture the start and time and the difference between start and end time after the completion of Write to Data Store Node execution.

    Yes, i agree with you that, Appian has to follow lot many set of steps before performing CRUD operation on DB. As Appian internally uses ORM (JPA, Hibernate) and ORM internally uses JDBC, so as per the JDBC internal mechanism, it has to follow various steps in order to perform any Operation on Relational Tabular Data store, these are:

    1. Obtain connection to DB
    2. Get a JDBC Statement
    3. Execute the Statement
    4. Close the Connection

    Now when we talk about the ORM's such as (Hibernate, JPA), it follows following steps:
    1. Create/Load the configuration
    2. Build the Sessionfactory
    3. Build the Session
    4. Access the Service (like CRUD operation)
    5. Close the Session

    Also as you have mention, when the network is slow or the database latency is more, we can expect to see more time lag
  • From my experience you cannot relate from node exec time to DB exec time. Appian is not built to execute a single node in minimal time, but to execute 100ks of processes with good performance.
  • @aloks176, In Process History->Process Nodes, we can find the duration for node completion, it clearly shows the time taken for the "Write to DB" node to complete. I agree with other points mentioned by you, the Obtain connection to DB, Get a JDBC statement - are the "Prepare" phase. The "Execute the statement" is the Execute phase and getting the results back is the transform phase.

    Appian logs do tell us what durations each of these phases took.
    But it does not tell us the duration for the remaining activities (the ones you mentioned - 1.Create/Load configuration 2.Build SessionFactory, 3.Build Session 4.Access the Service 5. Close the Session).

    Also, I am certain that a lot of post processing also happens.
    I tried a few things:
    1. I made the CDTs in which the output was being saved as "Hidden". I observed that I can save a few milliseconds per CDT
    2. If I simple do not save the output of write to DB node, I can save even more - which is desirable only if you don't care about the output of the write to DB node.

    @stefanh791, yes - I am also beginning to think that node exec time cannot be related to DB exec time. But, at-least if I had some confirmation about what post processing happens after the "transform" phase, it would have been helpful.
    A client I am working with is interested to know this.
    And I also find it surprising that a raw sql query takes 330 ms but the "Write to DB" node takes 770ms.
    I understand that Appian has layers of abstractions over a raw database query, and those take the remaining time. But, we are expecting a breakdown of them, or at-least a confirmation that all of this post-processing happens.
  • 0
    Certified Lead Developer
    @chetany One thing to take into account is that the Appian node execution time includes the "heartbeat" for validating the db thread, which is usually about the same as the fastest SQL execution time including network round trip. That would help explain the 330 to 770ms discrepancy.
  • @jims419, yes that could well be true