inspectIT/Ocelot

Vijayakumar Udupa

@vijayaudupa_twitter

Hi,
I have an instrumentation need, where in same method is being called twice as part of execution. I would like to retain some data between these calls for my metric computation.

Let me give a pseudo code for example.
`
public void doSomeActivity(){
//some initilization code here.
//first callto setStatus method.

  setStatus("STARTED");


//do some more business logic process, heavy lifting work.
 //second call to setStatus method.

  setStatus("COMPLETE");

//some more light steps here.

}
`
I'm trying to instrument "setStatus()" method, trying to push some data to inspectIt-context upon first call and try to retrive it when method is called for second time as part of same execution.
the instrumentation data element is set for both up-propagation & down-propagation (JVM_LOCAL) with is-tag = false.

But I can see that, inspectIT fails to propagate value set during first call of setStatus method to subsequent call of same method as part of same execution cycle.

Is there a way I can achieve this with in current inspectIT ocelot framework using yaml files it self? Any pointers is highly appreciated.

Jonas Kunz

@JonasKunz

Hi Vijayakumar,
Your approach is exactly the way to do it: enable JVM-local up- and down propagation for the data you want to correlate between these calls. Could you maybe show your instrumentation configuration yaml here?

Vijayakumar Udupa

@vijayaudupa_twitter

Sure. Here is our YAML file.

inspectit:

  tags:
    extra:
      prev_status:

  instrumentation:
    data:
      exec_in_process: {up-propagation: JVM_LOCAL,down-propagation: JVM_LOCAL, is-tag: false}
      prev_status : {up-propagation: GLOBAL, down-propagation: JVM_LOCAL, is-tag: true}

    scopes:
      updateRequestStatus:
        type:
          name: com.abcd.xyz.core.parser.ExpressionParser
        methods:
          - name: updateRequestStatus
    rules:
      entry:
          method_entry_time:
            action: timestamp_nanos
          method_name:
            action: get_method_fqn
          exec_flag:
            action: test_and_set_marker
            constant-input: { marker: exec_in_process}
      exit:
          method_duration:
            action: elapsed_millis
            data-input:
              sinceNanos: method_entry_time
          abcd_exec_status:
            action: check_and_count_exec
              data-input: {flag: exec_flag}

        metrics:
          '[abcd/exec/status]' : abcd_exec_status
          '[method/duration]' : method_duration    
    actions:  
       check_and_count_exec:
        input:
          _arg1: String
          flag: Boolean
        value-body: |
          if( !(_arg1.equalsIgnoreCase("PROCESSING")) && flag.booleanValue()== true) return new Integer(0);
          else return new Integer(1);

Jonas Kunz

@JonasKunz

Did yo ucheck the agent log for errors / warnings? I also recommend turning on debug logging to see if your method actually gets instrumented

In your pastet YAML you are missing the name of the rule and the usage of your scope but I guess that is a copy-paste error

Also I can't see the definitions of your metrics, could you post them aswell?

Vijayakumar Udupa

@vijayaudupa_twitter

I'm able to add system. Out messages and get confirmation. Instrumentation is happening, both method and above code segment is executed. I even printed items from _context.getData(). It has key, but no value

No errors in both agent log and exception log as well

I even printed thread name to verify both instances of method is called by single thread. (No reason to suspect otherwise)

Jonas Kunz

@JonasKunz

I guess you want to measure the elapsed duration between your two setRequestState calls? The easiest way to do this is by propagating the entry-timestamp using something like this:

inspectit:
  instrumentation:
    data:
      request_start_time:
        up-propagation: JVM_LOCAL
        down-propagation: JVM_LOCAL
        is-tag: false

    rules:
      your_rule:
        entry:
          is_start:
            action: is_arg1_equal
            constant-input: {value: "PROCESSING"}

          #only override the time if we are the start
          request_start_time:
            only-if-true: is_start
            action: timestamp_nanos
        exit:
          is_finish:
            action: is_arg1_equal
            constant-input: {value: "FINISHED"}
          request_duration:
            only-if-true: is_finish
            action: elapsed_millis
            data-input:
              sinceNanos: request_duration
        metrics:
          '[your/metric]' : method_duration   

    actions:  
      is_arg1_equal:
        input:
          _arg1: Object
          value: Object
        value: Boolean.valueOf(Objects.equals(_arg1,value))

Vijayakumar Udupa

@vijayaudupa_twitter

Thank you very much for your help. I will try this.

unknownuu

@unknownuu

Hi, I'm trying to enable traces for some methods Trace for only method is getting collected. How can we get trace for all it's sub methods as well? do we need to add all sub methods in scope ? or other direct way/config? Thanks in advance!

Jonas Kunz

@JonasKunz

Hi @unknownuu , yes you need to define a scope for all the sub-methods and trace it aswell.

unknownuu

@unknownuu

Thanks for your reply @JonasKunz .. I tried below 2 approaches and getting some trace logs but as not it is supposed to be Below is my scope definition scopes:
scopes:
tracemaintestReportmethod:
type:
name: com.org.test.controller.controllerTest
methods:

   - name: testReport

tracesubMethod: (sub method from other class invoked from 'testReport' main method)
type:
name: com.org.test.util.InputData
methods:

      - name: getId
      - name: setStatus

I tried to set rules as below
(Approach 1)
rules:
tracemaintestReportmethod:
tracing:
start-span: true
store-span: report_span_data
end-span: false
scopes:
tracemaintestReportmethod: true

  tracesubMethod_Trace:
    tracing:
      continue-span: report_span_data
    scopes:
      tracesubMethod: true

This approach didn't work for me

(Approach 2)
tracemaintestReportmethod:
tracing:
start-span: true
scopes:
tracemaintestReportmethod: true
tracesubMethod: true
In this approach traces are logged for only 'controllerTest' test class but for 'InputData' class no traces are logged.

If you can provide a sample example for collecting traces data that would help me a lot. or any link which explained this in detail will surely help me.

Jonas Kunz

@JonasKunz

Could you repaste your configuration using markdown, so that the indentation does not getl lost?

unknownuu

@unknownuu

Hi @JonasKunz , I did some modification in my scopes ( removed methods from main method)

'''scopes:
tracemaintestReportmethod:
type:
name: com.org.test.controller.controllerTest

tracesubMethod: (sub method from other class invoked from 'testReport' main method)
type:
name: com.org.test.util.InputData
methods:

  - name: getId
  - name: setStatus'''

and my rule config is as below
'''
rules:
tracemaintestReportmethod:
tracing:
start-span: true
scopes:
tracemaintestReportmethod: true
tracesubMethod: true
'''
With these configuration I am getting traces(method execution timings) for all the main class methods and mentioned sub methods of other classes(is my configurations correct? and to get details like query (if method executed a query) as in attached screenshot is there a extra configuration needed? or will it capture automatically.

unknownuu

@unknownuu

sorry, I tried using markdown for config still didn't get indented. But my actual config indentation query. my current requirement is as per above comment.

Jonas Kunz

@JonasKunz

Youn need to use triple backticks: `

unknownuu

@unknownuu

scopes:
  tracemaintestReportmethod:
    type:
      name: com.org.test.controller.controllerTest

  tracesubMethod: (sub method from other class invoked from  'testReport' main method)
    type:
      name: com.org.test.util.InputData
    methods:
      - name: getId
      - name: setStatus

rules:
  tracemaintestReportmethod:   
    tracing:
      start-span: true
    scopes:
      tracemaintestReportmethod: true
      tracesubMethod: true

Jonas Kunz

@JonasKunz

Yes, looks correct now

For JDBC trracing wit hdetails have a look at the configurations of the demo we provide

You'll most likely need a JDBC driver specific rule for the driver you are using (HSQLDB in the demo)

unknownuu

@unknownuu

Sure will check @JonasKunz . Thanks a lot. Don't we need to provide methods name in 'tracemaintestReportmethod' scope ?

Jonas Kunz

@JonasKunz

If you don't provide any methods, all methods of the given class with be instrumented

unknownuu

@unknownuu

Hi @JonasKunz , I tried to implemet JDBC tracing for MSSQL prepared statement by referring the HSQL db conf in demo app.
getting below exception. Database name gettting printed in trace but not SQL queries.
below is my instrumentation config

inspectit:
  instrumentation:
    data:
      db_name: {down-propagation: NONE, is-tag: false}
      sql: {down-propagation: NONE, is-tag: false}
      servicegraph_is_entry: {down-propagation: NONE, is-tag: false}
    scopes:
      mssqldb_prepared_statement_execute:
        type:
          name: com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement
        methods:
          - name: execute
            matcher-mode: STARTS_WITH
    rules:
      mssql_get_prep_statement_sql:
        scopes:
          mssqldb_prepared_statement_execute: true
        tracing:
          attributes:
            database: db_name
            sql: sql
        entry:
          db_name:
            action: get_jdbc_statement_connection_name
          sql:
            action: mssql_prepared_statement_get_sql
     actions:
        mssql_prepared_statement_get_sql:
        imports:
          - com.microsoft.sqlserver.jdbc
          - java.lang.reflect
        input:
          _this: SQLServerPreparedStatement
          _class: Class
        value-body: |
          Field sqlField = _class.getDeclaredField("sql");
          sqlField.setAccessible(true);
          return sqlField.get(_this);

      get_jdbc_statement_connection_name:
        imports:
          - java.sql
        input:
          _this: Statement
        value-body: |
          if(!_this.isClosed()) {
            Connection con = _this.getConnection();
            String url = con.getMetaData().getURL();

            int semiColonIndex = url.indexOf(';');
            if(semiColonIndex != -1) {
              url = url.substring(0,semiColonIndex);
            }

            int questionIndex = url.indexOf('?');
            if(questionIndex != -1) {
              url = url.substring(0,questionIndex);

When I execute with this configuration only DB name is getting logged in trace.
Encountering below exception.

2020-02-13 23:13:08,894 ERROR 81787820 --- [] [Bean#0_Worker-1] r.i.o.c.instrumentation.hook.MethodHook : Entry action Action 'mssql_prepared_statement_get_sql' for call 'sql' executed for method com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.executeQuery threw an exception and from now on is disabled!
java.lang.NoSuchFieldException: sql
at java.lang.Class.getDeclaredField(Class.java:2070)
at com.sun.proxy.inspectitGen

KaTeX parse error: Can't use function '$' in math mode at position 1: $̲557729609728220…: $5577296097282200557.executeImpl(GenericActionTemplate.java)
        at com.sun.proxy.inspectitGen

$5577296097282200557.execute(GenericActionTemplate.java:24)
at rocks.inspectit.ocelot.core.instrumentation.actions.bound.NonVoidDynamicBoundGenericAction.execute(NonVoidDynamicBoundGenericAction.java:28)
at rocks.inspectit.ocelot.core.instrumentation.hook.MethodHook.onEnter(MethodHook.java:61)
at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.executeQuery(SQLServerPreparedStatement.java:429)
at org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:96)
at org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:96)
at sun.reflect.GeneratedMethodAccessor904.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at net.bull.javamelody.JdbcWrapper.doExecute(JdbcWrapper.java:412)
at net.bull.javamelody.JdbcWrapper$StatementInvocationHandler.invoke(JdbcWrapper.java:137)
at net.bull.javamelody.JdbcWrapper$DelegatingInvocationHandler.invoke(JdbcWrapper.java:294)
at com.sun.proxy.$Proxy498.executeQuery(Unknown Source)
at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:70)

Can you please help me with this.! Thanks

Jonas Kunz

@JonasKunz

The action mssql_prepared_statement_get_sql tries to lookup an sql private field of the given SQLServerPreparedStatement class. This field doesn't exist, therefore you get the NoSuchFieldException. Have a look at the source code:
https://jar-download.com/artifacts/com.microsoft.sqlserver/mssql-jdbc/6.1.0.jre8/source-code/com/microsoft/sqlserver/jdbc/SQLServerPreparedStatement.java
You instead need to use the field sqlCommand.

Marius Oehler

@mariusoe

Hi,
when we tried to instrument MSSQL the last time, we had to use the userSQL field instead sql because the other ones where not populated all the time. Maybe you can try this field aswell.

unknownuu

@unknownuu

Thanks @JonasKunz , @mariusoe ... 'userSQL ' worked fines.!

tgrperf

@tgrperf

Hello,

tgrperf

@tgrperf

I implement JDBC tracing for Oracle prepared statement based on the hsql db conf in demo app.but no sql traces shown, only database trace is displayed.

Here is my conf :

inspectit:
instrumentation:

data:
  db_name: {down-propagation: NONE, is-tag: false}
  sql: {down-propagation: NONE, is-tag: false}
  servicegraph_is_entry: {down-propagation: NONE, is-tag: false}

scopes:
  oracle_prepared_statement_execute:
    type:
      name: oracle.jdbc.OraclePreparedStatement
    methods:
      - name: execute
        matcher-mode: STARTS_WITH

rules:
  # Extract the sql and add it to the trace
  oracle_get_prep_statement_sql:
    scopes:
      oracle_prepared_statement_execute: true
    tracing:
      attributes:
        database: db_name
        sql: sql
    entry:
      db_name:
        action: get_jdbc_statement_connection_name
      sql:
        action: oracle_prepared_statement_get_sql

  # We also trace JDBC calls including their target database
  servicegraph_record_jdbc_calls:
    tracing:
      start-span: true
      attributes:
        database: db_name
      start-span-conditions:
        only-if-true: servicegraph_is_entry
    entry:
      db_name:
        action: get_jdbc_statement_connection_name


actions:

Extracts the SQL from a PreparedStatement for ORACLEDB

  oracle_prepared_statement_get_sql:
    imports:
      - oracle.jdbc
      - java.lang.reflect
    input:
      _this: OraclePreparedStatement
      _class: Class
    value-body:
      Field sqlField = _class.getDeclaredField("sql");
      sqlField.setAccessible(true);
      return sqlField.get(_this);

tgrperf

@tgrperf

no errors shown in log files.

tgrperf

@tgrperf

Jonas Kunz

@JonasKunz

You should see an error in the logs because there is no "sql" Field for Oracle

You need to use this method to extract the sql:
https://github.com/caot/ojdbc6-11.2.0.2.0.src/blob/master/src/oracle/jdbc/driver/OracleStatement.java#L2688

tgrperf

@tgrperf

Hello,

oracle_prepared_statement_get_sql action was'nt triggered at all !! and my log files does'nt show any errors.so i add sql entry to servicegraph_record_jdbc_calls (sql:
action: get_oracle_prepared_statement_sql
and my

tgrperf

@tgrperf

action is now triggered and i can see "sql" Field error in traces. after replacing sql field with originalSql one , sql queries are shown now in zipkin.

Thanks a lot.

tgrperf

@tgrperf

Hello, now i would like to show business services called through http servlets in zipkin.is there a way to link instrumented services/api to their http calling requests?

Jonas Kunz

@JonasKunz

What do you mean by "show business services" ? You can (a) add attributes to your traces identifying your business transaction or (b) trace the methods identifying your business transaction

tgrperf

@tgrperf

i mean (a) , add methods' name of business transactions processed in one http request.as for (b) , this is already done in my config files, and i can view all my business transactions with response time but in isolation from http requests.

something like this :

so i wonder how can i add business & dao transactions to my http request tracing in zipkin.

Jonas Kunz

@JonasKunz

You need to instrument the methods of your services, have a look at the following part of the documentation:
https://inspectit.github.io/inspectit-ocelot/docs/instrumentation/scopes

Where communities thrive

People

Repo info

Activity

Extracts the SQL from a PreparedStatement for ORACLEDB