Issue #896 - Prometheus metrics and telemetry

[bbc88ks]

Implements #896
This PR instruments argo with basic workflow metrics and golang telemetry. It's heavily influenced by https://github.com/kubernetes/kube-state-metrics and is disabled by default. It has to be explicitly configured in the ConfigMap, e.g.:

config: |
    metricsConfig:
      enabled: true
      path: /metrics
      port: :8080
    telemetryConfig:
      enabled: true
      path: /metrics
      port: :8081

I made it use the same informer and allow a user to override the workflow resync period to get metrics more often ( 1 minute I think would be optimal). The other option I am thinking about is running it in a sidecar, but it makes it more difficult to make sure configs do not diverge and use the same label selectors. It also seems reasonable that the controller itself reports the metrics and I can see that extended into a more detailed node transition metrics at some point.

I am looking for feedback and still working on some doc updates.

Example metrics reported:

# HELP kube_wf_completion_time Completion time in unix timestamp for a workflow.
# TYPE kube_wf_completion_time gauge
kube_wf_completion_time{name="coinflip-recursive-764t8",namespace="default"} 1.533107473e+09
kube_wf_completion_time{name="coinflip-recursive-pnk4v",namespace="default"} 1.533144282e+09
kube_wf_completion_time{name="coinflip-recursive-rvg67",namespace="default"} 1.533144285e+09
kube_wf_completion_time{name="coinflip-recursive-xsd48",namespace="default"} 1.533135655e+09
kube_wf_completion_time{name="coinflip-recursive-z7bqz",namespace="default"} 1.533144296e+09
kube_wf_completion_time{name="retry-script-d9snk",namespace="default"} 1.533310909e+09
kube_wf_completion_time{name="retry-script-js9jf",namespace="default"} 1.533310932e+09
# HELP kube_wf_created Creation time in unix timestamp for a workflow.
# TYPE kube_wf_created gauge
kube_wf_created{name="coinflip-recursive-764t8",namespace="default"} 1.533107468e+09
kube_wf_created{name="coinflip-recursive-pnk4v",namespace="default"} 1.533144273e+09
kube_wf_created{name="coinflip-recursive-rvg67",namespace="default"} 1.533144275e+09
kube_wf_created{name="coinflip-recursive-xsd48",namespace="default"} 1.533135646e+09
kube_wf_created{name="coinflip-recursive-z7bqz",namespace="default"} 1.533144264e+09
kube_wf_created{name="retry-script-d9snk",namespace="default"} 1.533310906e+09
kube_wf_created{name="retry-script-js9jf",namespace="default"} 1.533310904e+09
# HELP kube_wf_info Information about workflow.
# TYPE kube_wf_info gauge
kube_wf_info{entrypoint="coinflip",name="coinflip-recursive-764t8",namespace="default",service_account_name="argo",templates="coinflip,flip-coin,heads"} 1
kube_wf_info{entrypoint="coinflip",name="coinflip-recursive-pnk4v",namespace="default",service_account_name="argo",templates="coinflip,flip-coin,heads"} 1
kube_wf_info{entrypoint="coinflip",name="coinflip-recursive-rvg67",namespace="default",service_account_name="argo",templates="coinflip,flip-coin,heads"} 1
kube_wf_info{entrypoint="coinflip",name="coinflip-recursive-xsd48",namespace="default",service_account_name="argo",templates="coinflip,flip-coin,heads"} 1
kube_wf_info{entrypoint="coinflip",name="coinflip-recursive-z7bqz",namespace="default",service_account_name="argo",templates="coinflip,flip-coin,heads"} 1
kube_wf_info{entrypoint="retry-script",name="retry-script-d9snk",namespace="default",service_account_name="argo",templates="retry-script"} 1
kube_wf_info{entrypoint="retry-script",name="retry-script-js9jf",namespace="default",service_account_name="argo",templates="retry-script"} 1
# HELP kube_wf_start_time Start time in unix timestamp for a workflow.
# TYPE kube_wf_start_time gauge
kube_wf_start_time{name="coinflip-recursive-764t8",namespace="default"} 1.533107468e+09
kube_wf_start_time{name="coinflip-recursive-pnk4v",namespace="default"} 1.533144273e+09
kube_wf_start_time{name="coinflip-recursive-rvg67",namespace="default"} 1.533144275e+09
kube_wf_start_time{name="coinflip-recursive-xsd48",namespace="default"} 1.533135646e+09
kube_wf_start_time{name="coinflip-recursive-z7bqz",namespace="default"} 1.533144264e+09
kube_wf_start_time{name="retry-script-d9snk",namespace="default"} 1.533310906e+09
kube_wf_start_time{name="retry-script-js9jf",namespace="default"} 1.533310904e+09
# HELP kube_wf_status_phase The workflow current phase.
# TYPE kube_wf_status_phase gauge
kube_wf_status_phase{name="coinflip-recursive-764t8",namespace="default",phase="Error"} 0
kube_wf_status_phase{name="coinflip-recursive-764t8",namespace="default",phase="Failed"} 0
kube_wf_status_phase{name="coinflip-recursive-764t8",namespace="default",phase="Running"} 0
kube_wf_status_phase{name="coinflip-recursive-764t8",namespace="default",phase="Skipped"} 0
kube_wf_status_phase{name="coinflip-recursive-764t8",namespace="default",phase="Succeeded"} 1
kube_wf_status_phase{name="coinflip-recursive-pnk4v",namespace="default",phase="Error"} 0
kube_wf_status_phase{name="coinflip-recursive-pnk4v",namespace="default",phase="Failed"} 0
kube_wf_status_phase{name="coinflip-recursive-pnk4v",namespace="default",phase="Running"} 0
kube_wf_status_phase{name="coinflip-recursive-pnk4v",namespace="default",phase="Skipped"} 0
kube_wf_status_phase{name="coinflip-recursive-pnk4v",namespace="default",phase="Succeeded"} 1
kube_wf_status_phase{name="coinflip-recursive-rvg67",namespace="default",phase="Error"} 0
kube_wf_status_phase{name="coinflip-recursive-rvg67",namespace="default",phase="Failed"} 0
kube_wf_status_phase{name="coinflip-recursive-rvg67",namespace="default",phase="Running"} 0
kube_wf_status_phase{name="coinflip-recursive-rvg67",namespace="default",phase="Skipped"} 0
kube_wf_status_phase{name="coinflip-recursive-rvg67",namespace="default",phase="Succeeded"} 1
kube_wf_status_phase{name="coinflip-recursive-xsd48",namespace="default",phase="Error"} 0
kube_wf_status_phase{name="coinflip-recursive-xsd48",namespace="default",phase="Failed"} 0
kube_wf_status_phase{name="coinflip-recursive-xsd48",namespace="default",phase="Running"} 0
kube_wf_status_phase{name="coinflip-recursive-xsd48",namespace="default",phase="Skipped"} 0
kube_wf_status_phase{name="coinflip-recursive-xsd48",namespace="default",phase="Succeeded"} 1
kube_wf_status_phase{name="coinflip-recursive-z7bqz",namespace="default",phase="Error"} 0
kube_wf_status_phase{name="coinflip-recursive-z7bqz",namespace="default",phase="Failed"} 0
kube_wf_status_phase{name="coinflip-recursive-z7bqz",namespace="default",phase="Running"} 0
kube_wf_status_phase{name="coinflip-recursive-z7bqz",namespace="default",phase="Skipped"} 0
kube_wf_status_phase{name="coinflip-recursive-z7bqz",namespace="default",phase="Succeeded"} 1
kube_wf_status_phase{name="retry-script-d9snk",namespace="default",phase="Error"} 0
kube_wf_status_phase{name="retry-script-d9snk",namespace="default",phase="Failed"} 0
kube_wf_status_phase{name="retry-script-d9snk",namespace="default",phase="Running"} 0
kube_wf_status_phase{name="retry-script-d9snk",namespace="default",phase="Skipped"} 0
kube_wf_status_phase{name="retry-script-d9snk",namespace="default",phase="Succeeded"} 1
kube_wf_status_phase{name="retry-script-js9jf",namespace="default",phase="Error"} 0
kube_wf_status_phase{name="retry-script-js9jf",namespace="default",phase="Failed"} 0
kube_wf_status_phase{name="retry-script-js9jf",namespace="default",phase="Running"} 0
kube_wf_status_phase{name="retry-script-js9jf",namespace="default",phase="Skipped"} 0
kube_wf_status_phase{name="retry-script-js9jf",namespace="default",phase="Succeeded"} 1

Example telemetry reported:

# HELP go_gc_duration_seconds A summary of the GC invocation durations.
# TYPE go_gc_duration_seconds summary
go_gc_duration_seconds{quantile="0"} 2.8945e-05
go_gc_duration_seconds{quantile="0.25"} 4.4515e-05
go_gc_duration_seconds{quantile="0.5"} 5.7129e-05
go_gc_duration_seconds{quantile="0.75"} 8.6191e-05
go_gc_duration_seconds{quantile="1"} 0.001410591
go_gc_duration_seconds_sum 0.106484697
go_gc_duration_seconds_count 865
# HELP go_goroutines Number of goroutines that currently exist.
# TYPE go_goroutines gauge
go_goroutines 58
# HELP go_memstats_alloc_bytes Number of bytes allocated and still in use.
# TYPE go_memstats_alloc_bytes gauge
go_memstats_alloc_bytes 6.525976e+06
# HELP go_memstats_alloc_bytes_total Total number of bytes allocated, even if freed.
# TYPE go_memstats_alloc_bytes_total counter
go_memstats_alloc_bytes_total 2.96083752e+09
# HELP go_memstats_buck_hash_sys_bytes Number of bytes used by the profiling bucket hash table.
# TYPE go_memstats_buck_hash_sys_bytes gauge
go_memstats_buck_hash_sys_bytes 1.508331e+06
# HELP go_memstats_frees_total Total number of frees.
# TYPE go_memstats_frees_total counter
go_memstats_frees_total 9.258784e+06
# HELP go_memstats_gc_sys_bytes Number of bytes used for garbage collection system metadata.
# TYPE go_memstats_gc_sys_bytes gauge
go_memstats_gc_sys_bytes 610304
# HELP go_memstats_heap_alloc_bytes Number of heap bytes allocated and still in use.
# TYPE go_memstats_heap_alloc_bytes gauge
go_memstats_heap_alloc_bytes 6.525976e+06
# HELP go_memstats_heap_idle_bytes Number of heap bytes waiting to be used.
# TYPE go_memstats_heap_idle_bytes gauge
go_memstats_heap_idle_bytes 2.408448e+06
# HELP go_memstats_heap_inuse_bytes Number of heap bytes that are in use.
# TYPE go_memstats_heap_inuse_bytes gauge
go_memstats_heap_inuse_bytes 8.27392e+06
# HELP go_memstats_heap_objects Number of allocated objects.
# TYPE go_memstats_heap_objects gauge
go_memstats_heap_objects 36519
# HELP go_memstats_heap_released_bytes_total Total number of heap bytes released to OS.
# TYPE go_memstats_heap_released_bytes_total counter
go_memstats_heap_released_bytes_total 0
# HELP go_memstats_heap_sys_bytes Number of heap bytes obtained from system.
# TYPE go_memstats_heap_sys_bytes gauge
go_memstats_heap_sys_bytes 1.0682368e+07
# HELP go_memstats_last_gc_time_seconds Number of seconds since 1970 of last garbage collection.
# TYPE go_memstats_last_gc_time_seconds gauge
go_memstats_last_gc_time_seconds 1.5335726956311252e+09
# HELP go_memstats_lookups_total Total number of pointer lookups.
# TYPE go_memstats_lookups_total counter
go_memstats_lookups_total 11740
# HELP go_memstats_mallocs_total Total number of mallocs.
# TYPE go_memstats_mallocs_total counter
go_memstats_mallocs_total 9.295303e+06
# HELP go_memstats_mcache_inuse_bytes Number of bytes in use by mcache structures.
# TYPE go_memstats_mcache_inuse_bytes gauge
go_memstats_mcache_inuse_bytes 3472
# HELP go_memstats_mcache_sys_bytes Number of bytes used for mcache structures obtained from system.
# TYPE go_memstats_mcache_sys_bytes gauge
go_memstats_mcache_sys_bytes 16384
# HELP go_memstats_mspan_inuse_bytes Number of bytes in use by mspan structures.
# TYPE go_memstats_mspan_inuse_bytes gauge
go_memstats_mspan_inuse_bytes 96216
# HELP go_memstats_mspan_sys_bytes Number of bytes used for mspan structures obtained from system.
# TYPE go_memstats_mspan_sys_bytes gauge
go_memstats_mspan_sys_bytes 114688
# HELP go_memstats_next_gc_bytes Number of heap bytes when next garbage collection will take place.
# TYPE go_memstats_next_gc_bytes gauge
go_memstats_next_gc_bytes 6.831808e+06
# HELP go_memstats_other_sys_bytes Number of bytes used for other system allocations.
# TYPE go_memstats_other_sys_bytes gauge
go_memstats_other_sys_bytes 644365
# HELP go_memstats_stack_inuse_bytes Number of bytes in use by the stack allocator.
# TYPE go_memstats_stack_inuse_bytes gauge
go_memstats_stack_inuse_bytes 819200
# HELP go_memstats_stack_sys_bytes Number of bytes obtained from system for stack allocator.
# TYPE go_memstats_stack_sys_bytes gauge
go_memstats_stack_sys_bytes 819200
# HELP go_memstats_sys_bytes Number of bytes obtained by system. Sum of all system allocations.
# TYPE go_memstats_sys_bytes gauge
go_memstats_sys_bytes 1.439564e+07
# HELP process_cpu_seconds_total Total user and system CPU time spent in seconds.
# TYPE process_cpu_seconds_total counter
process_cpu_seconds_total 68.01
# HELP process_max_fds Maximum number of open file descriptors.
# TYPE process_max_fds gauge
process_max_fds 65536
# HELP process_open_fds Number of open file descriptors.
# TYPE process_open_fds gauge
process_open_fds 11
# HELP process_resident_memory_bytes Resident memory size in bytes.
# TYPE process_resident_memory_bytes gauge
process_resident_memory_bytes 3.1113216e+07
# HELP process_start_time_seconds Start time of the process since unix epoch in seconds.
# TYPE process_start_time_seconds gauge
process_start_time_seconds 1.53352945857e+09
# HELP process_virtual_memory_bytes Virtual memory size in bytes.
# TYPE process_virtual_memory_bytes gauge
process_virtual_memory_bytes 1.87838464e+08

[jessesuen]

Thanks for this contribution! I really think this adds a lot of value to the controller.

I'm concerned about the removal of common.LabelKeyCompleted label when metrics are enabled. The point of the label was to prevent the controller from watching/reprocessing workflows it no longer cares about. So by enabling metrics, we'll have vastly different scalability characteristics of the controller since the controller will be forced to operate on old workflows it no longer cares about after each resync period. It seems like we may be overloading the responsibilities of the controller a bit here.

Instead of adjusting the main informer/control loop, I think it will be better to introduce a second control loop/informer/workers specifically for metrics which ignores the label and has the lower 1 minute resync period that you are suggesting.

The other option I am thinking about is running it in a sidecar

I think we could instead launch this as as separate goroutines from the main control loop.

[jessesuen]

It looks like the Gopkg.lock file was generated using the older dep v0.4. The lock file is now being maintained using dep v0.5.0. Please update your dep for consistency.

[bbc88ks]

Yeah, I've actually started with my own generic shared informer, cause I wanted to decouple it as much as possible. But then I ran into the same unmarshalling issue.

[bbc88ks]

@jessesuen I switched it to a dedicated informer. Let me know what you think, so I can address the feedback before finalizing the docs.

[jessesuen]

@bbc88ks Looks good to go. Theres one lint check that failed which needs to be fixed before merging:

workflow/metrics/server.go:25:17:warning: error return value not checked (defer srv.Close()) (errcheck)

Also please update CHANGELOG.md and credit yourself for the contribution!

[discordianfish]

Why is this split into two listeners? That's not very common.
I'm also not sure about the overhead of using the informer to capture this, but it seems like exposing the metrics 'when they happen' would be better (e.g set the start time metric when the controller actually creates the workflow).