PSQL Slow Statement logs in Skywalking (kubernetes instance)

[azibhassan]

Hi,

I am trying to setup Postgres Slow statements logs and have been following demo example given at link.

As of now, I am not seeing any logs showing up in skywalking instance. Not sure what I am missing.

Following are the logs from fluent-bit service. I validated the json output and fluent-bit service is able to send logs via http://:13800/v3/logs:
[{"date":1714356754.055633,"body":{"json":{"json":"{\"layer\":\"POSTGRESQL\",\"statement\":\"SELECT\",\"id\":\"34bacb9e-aea6-6246-49e5-14ace3d4848c\",\"query_time\":14,\"service\":\"postgresql::datastore\",\"time\":1714356754}"}},"layer":"POSTGRESQL","service":"postgresql::datastore","tags":{"data":[{"value":"SLOW_SQL","key":"LOG_KIND"}]}}] [2024/04/29 02:12:34] [ info] [output:http:http.1] skywalking-oap.aks-istio-system:13800, HTTP status=200
[{"date":1714356814.167202,"body":{"json":{"json":"{\"layer\":\"POSTGRESQL\",\"statement\":\"SELECT\",\"id\":\"81181e64-651c-c215-eb3f-ee1bca4ee8ce\",\"query_time\":13,\"service\":\"postgresql::datastore\",\"time\":1714356814}"}},"layer":"POSTGRESQL","service":"postgresql::datastore","tags":{"data":[{"value":"SLOW_SQL","key":"LOG_KIND"}]}}] [2024/04/29 02:13:34] [ info] [output:http:http.1] skywalking-oap.aks-istio-system:13800, HTTP status=200

On postgres database service, I am only seeing duplicate entry errors except the following one which I dont think is related to psql slow statements:
2024-04-29 02:05:23.038 GMT [2773] ERROR: relation "top_n_database_statement_19700120" does not exist at character 13 2024-04-29 02:05:23.038 GMT [2773] STATEMENT: INSERT INTO top_n_database_statement_19700120(id,table_name,statement,latency,trace_id,entity_id,timestamp,time_bucket) VALUES ($1,$2,$3,$4,$5,$6,$7,$8)

While looking at skywalking-oap logs, I do not see error. Just seeing removal of data after certain time.
Following are the environment variables values which I am using for skywalking:

SW_HEALTH_CHECKER_INTERVAL_SECONDS: 30 
SW_RECEIVER_ZIPKIN: default
SW_QUERY_ZIPKIN: default
SW_ZIPKIN_HTTP_COLLECTOR_ENABLED: true
SW_RECEIVER_ZIPKIN_REST_HOST: 0.0.0.0
SW_RECEIVER_ZIPKIN_REST_PORT: 9411
SW_ENVOY_METRIC: default
SW_ENVOY_METRIC_SERVICE: true
SW_ENVOY_METRIC_ALS_HTTP_ANALYSIS: mx-mesh,k8s-mesh,persistence
SW_ENVOY_METRIC_ALS_TCP_ANALYSIS: mx-mesh,k8s-mesh,persistence
SW_LOG_ANALYZER: default
SW_LOG_LAL_FILES: mesh-dp,pgsql-slowsql,redis-slowsql,k8s-service
SW_OTEL_RECEIVER_ENABLED_HANDLERS: otlp,otlp-metrics,otlp-logs,otlp-traces
K8S_SERVICE_NAME_RULE: "app::${service.metadata.name}.${service.metadata.namespace}"
SW_ENABLE_ON_DEMAND_POD_LOG: true
SW_TELEMETRY: prometheus
SW_TELEMETRY_PROMETHEUS_HOST: 0.0.0.0
SW_TELEMETRY_PROMETHEUS_PORT: 1234
SW_ENABLE_UPDATE_UI_TEMPLATE: true
SW_METER_ANALYZER_ACTIVE_FILES: satellite,network-profiling,continuous-profiling
SW_SLOW_DB_THRESHOLD: default:10,mongodb:100
SW_RECEIVER_SHARING_REST_HOST: 0.0.0.0
SW_RECEIVER_SHARING_REST_PORT: 13800
SW_RECEIVER_SHARING_REST_CONTEXT_PATH: /
SW_SEARCHABLE_LOGS_TAG_KEYS: level,http.status_code
SW_SEARCHABLE_TAG_KEYS: http.method,http.status_code,rpc.status_code,db.type,db.instance

Is there any setting which I am missing on skywalking oap instance?
Is it possible to verify via database that entries were added to table properly?

Please let me know if any further logs are required. I am relatively new to skywalking and would really appreciate any suggestions

Skywalking v9.7.0
fluent bit v3.0.2

[wu-sheng]

@yswdqz may know more.

By looking at these logs, I assume you have the wrong timestamp. \"time\":1714356754 and relation "top_n_database_statement_19700120" does not exist at character 13
1970 usually means you are using second rather than ms as timestamp unit.

[yswdqz]

Yes, it looks like a timestamp issue where top_n_database_statement_19700120 would be considered data from 1970/01/20 and thus be deleted for being out of date

[yswdqz]

I think I found the problem. The fluent-bit configuration in showcase is somewhat outdated, and I'll be changing it in the near future. Instead, please use this configuration：

https://github.com/apache/skywalking/blob/master/test/e2e-v2/cases/postgresql/postgres-exporter/fluent-bit-script.lua

[azibhassan]

If you dont mind answering me this as well, is it possible to include more than just top statement. After fixing the bug, I am seeing time taken and only "SELECT" command. Possible to add more than just select? Will it be related to psql configuration or lua script ?

[yswdqz]

We are simply extracting the slow sql data from the log and are not restricting the type of statement. However, for demo, it's not so easy to make statements other than select generate slow sql logs: select can use the sleep function.

[azibhassan]

In that case, I probably need to update postgres configuration for my psql instance. Thanks for info

[wu-sheng]

Try to change this

https://github.com/apache/skywalking-showcase/blob/dae1bd866790eebc51c7737fff0c83fe7c1b1587/deploy/platform/kubernetes/templates/feature-postgresql-monitor/fluent-bit.yaml#L68

It should be re1["time"] = os.time() * 1000. This is a demo bug.

[azibhassan]

This was it. Thank you for your help.

[wu-sheng]

If you have time, you could send a pull request to fix it. :)

[azibhassan]

Done. Thanks again
apache/skywalking-showcase#169