Strange behavior with MAP command and actions deployed with concurrency limit greater than one.

[alfredo-milani]

System

• MacBook Pro 13'' 2017
• Docker Desktop (v.2.5.0.1)
• Kubernetes (v.1.19.3)
• opewhisk-composer (v.0.12.0)

Deployment

OpenWhisk platform has been deployed using the following commands (https://github.com/apache/openwhisk-deploy-kube/blob/master/README.md):

kubectl label nodes --all openwhisk-role=invoker
helm install owdev "/.../openwhisk-deploy-kube/helm/openwhisk" \
    -n openwhisk --create-namespace -f "/.../openwhisk-deploy-kube/my_cluster.yaml"

File "my_cluster.yaml" contains:

whisk:
  ingress:
    type: NodePort
    apiHostName: 192.168.65.3
    apiHostPort: 31001
  limits:
    actionsInvokesPerminute: 500
    actionsInvokesConcurrent: 50
    triggersFiresPerminute: 200
    actionsSequenceMaxlength: 70
    actions:
      time:
        min: "100ms"
        max: "5m"
        std: "1m"
      memory:
        min: "128m"
        max: "512m"
        std: "256m"
      concurrency:
        min: 1
        max: 20
        std: 1
      log:
        min: "0m"
        max: "10m"
        std: "10m"
    activation:
      payload:
        max: "1048576"

nginx:
  httpsNodePort: 31001

invoker:
  containerFactory:
    enableConcurrency: true
  options: "-Dwhisk.spi.LogStoreProvider=org.apache.openwhisk.core.containerpool.logging.LogDriverLogStoreProvider -Dwhisk.containerPool.akkaClient=true"

metrics:
  prometheusEnabled: true
  userMetricsEnabled: true

Composition file

const composer = require('openwhisk-composer')

module.exports = composer.sequence(
    composer.action('generator'),
    composer.action('splitter'),
    composer.map('fn1', 'fn2', 'fn3'),
    composer.action('global')
)

Behavior

Once deployed all actions with concurrency limit greater than 1 (I tested with 2, 5, 10, 15, 20), the output of the command wsk -i activation list results in:

Datetime            Activation ID                    Kind      Start Duration   Status  Entity
2020-12-24 01:12:41 4c1fe8f1c8f7408d9fe8f1c8f7a08d04 nodejs:10 warm  45ms       success guest/process_cmp:0.0.2
2020-12-24 01:12:40 be9b99a395a64aac9b99a395a6faac18 nodejs:10 cold  467ms      success guest/global:0.0.1
2020-12-24 01:12:39 8f6a6ef1e7454ce0aa6ef1e7458ce0dc nodejs:10 warm  16ms       success guest/process_cmp:0.0.2
2020-12-24 01:12:39 0cab10a9612144a7ab10a9612144a775 nodejs:10 cold  79ms       success guest/echo:0.0.1
2020-12-24 01:11:49 908844645dbc45838844645dbca5837e nodejs:10 warm  48.321s    success guest/process_cmp:0.0.2
2020-12-24 01:11:49 8c549e0ca77544ec949e0ca775b4ec37 nodejs:10 warm  48.468s    success guest/process_cmp:0.0.2
2020-12-24 01:11:48 5a67e692d72e4ef2a7e692d72e1ef202 nodejs:10 warm  116ms      success guest/fn3:0.0.1
2020-12-24 01:11:48 4988b60f25d2456288b60f25d2356272 nodejs:10 cold  472ms      success guest/fn3:0.0.1
2020-12-24 01:11:46 7b056d4ce3dc4bbb856d4ce3dcfbbbe5 nodejs:10 warm  194ms      success guest/process_cmp:0.0.2
2020-12-24 01:11:46 cb9644cbe9534a359644cbe9534a3580 nodejs:10 warm  123ms      success guest/process_cmp:0.0.2
2020-12-24 01:11:46 f86721155a324b65a721155a32bb652f nodejs:10 warm  21ms       success guest/fn2:0.0.1
2020-12-24 01:11:46 902b4aa654c04f71ab4aa654c02f7155 nodejs:10 cold  105ms      success guest/fn2:0.0.1
2020-12-24 01:11:45 2796dc61d1e54dd896dc61d1e52dd830 nodejs:10 warm  83ms       success guest/process_cmp:0.0.2
2020-12-24 01:11:45 3f16c02dd809465496c02dd809d65459 nodejs:10 warm  32ms       success guest/process_cmp:0.0.2
2020-12-24 01:11:44 f96cd601ccc14757acd601ccc15757c1 nodejs:10 warm  24ms       success guest/fn1:0.0.1
2020-12-24 01:11:44 6b528243ac354264928243ac35126482 nodejs:10 cold  202ms      success guest/fn1:0.0.1
2020-12-24 01:11:44 5287c5e8337144ea87c5e83371f4ea5c nodejs:10 warm  15ms       success guest/process_cmp:0.0.2
2020-12-24 01:11:44 4eca5d53864540738a5d538645907317 nodejs:10 warm  10ms       success guest/process_cmp:0.0.2
2020-12-24 01:11:44 3dac565d34dd41c8ac565d34dd91c823 sequence  warm  54.355s    success guest/process_cmp:0.0.2
2020-12-24 01:11:43 6dd2535b3e05487392535b3e05c873ed sequence  warm  54.402s    success guest/process_cmp:0.0.2
2020-12-24 01:11:43 b5899085af6a44f1899085af6aa4f1aa nodejs:10 warm  55.044s    success guest/process_cmp:0.0.2
2020-12-24 01:11:42 44f71adb9205488cb71adb9205c88cff nodejs:10 cold  107ms      success guest/splitter:0.0.1
2020-12-24 01:11:41 ff1cb1f62e6445039cb1f62e6495037c nodejs:10 warm  24ms       success guest/process_cmp:0.0.2
2020-12-24 01:11:40 00b5adb6bb9e4dc0b5adb6bb9e8dc088 nodejs:10 cold  271ms      success guest/generator:0.0.1
2020-12-24 01:11:39 1fc1f090b83f498181f090b83fa98133 nodejs:10 cold  322ms      success guest/process_cmp:0.0.2
2020-12-24 01:11:38 1c804ece19554b74804ece1955eb74aa sequence  warm  1m3.74s    success guest/process_cmp:0.0.2

Deploying all actions with concurrency limit of 1, the command wsk -i activation list, results in:

Datetime            Activation ID                    Kind      Start Duration   Status  Entity
2020-12-30 03:07:40 e7b4f6f13d574715b4f6f13d571715ce nodejs:10 warm  51ms       success guest/process_cmp:0.0.3
2020-12-30 03:07:39 45458e7de51446c9858e7de51476c9da nodejs:10 cold  143ms      success guest/global:0.0.2
2020-12-30 03:07:38 a20f2d65c7424db88f2d65c742edb86e nodejs:10 warm  54ms       success guest/process_cmp:0.0.3
2020-12-30 03:07:37 664af41682ca43c48af41682cab3c493 nodejs:10 cold  589ms      success guest/fn3:0.0.2
2020-12-30 03:07:37 3bed3685494a49a8ad3685494a59a854 nodejs:10 warm  114ms      success guest/process_cmp:0.0.3
2020-12-30 03:07:35 d03d7bb8eba240d9bd7bb8eba240d930 nodejs:10 cold  1.39s      success guest/fn3:0.0.2
2020-12-30 03:07:33 a3d3d80874a7408893d80874a7b088ab nodejs:10 warm  31ms       success guest/process_cmp:0.0.3
2020-12-30 03:07:32 00206d4a71d04662a06d4a71d0f66278 nodejs:10 cold  596ms      success guest/fn2:0.0.2
2020-12-30 03:07:30 4236ca3f909a4949b6ca3f909a894983 nodejs:10 warm  55ms       success guest/process_cmp:0.0.3
2020-12-30 03:07:29 b69632dee784489d9632dee784f89d42 nodejs:10 cold  176ms      success guest/fn2:0.0.2
2020-12-30 03:07:29 8854a1040d42483e94a1040d42d83e82 nodejs:10 warm  11ms       success guest/process_cmp:0.0.3
2020-12-30 03:07:29 1ae3dc5c0d314d08a3dc5c0d31cd0880 nodejs:10 warm  27ms       success guest/fn1:0.0.2
2020-12-30 03:07:29 a9627bb5899e4346a27bb5899ef346c2 nodejs:10 cold  170ms      success guest/process_cmp:0.0.3
2020-12-30 03:07:28 db61afb2a1fc4c0fa1afb2a1fc8c0fab nodejs:10 warm  176ms      success guest/process_cmp:0.0.3
2020-12-30 03:07:27 e2e788fcaff6424aa788fcaff6624ac8 nodejs:10 cold  265ms      success guest/fn1:0.0.2
2020-12-30 03:07:24 36f41f49d0c14d09b41f49d0c11d0984 nodejs:10 cold  224ms      success guest/process_cmp:0.0.3
2020-12-30 03:07:24 953f42494327425abf42494327625a0a sequence  warm  13.864s    success guest/process_cmp:0.0.3
2020-12-30 03:07:24 60ff7ef4595b41ddbf7ef4595b01ddb0 sequence  warm  14.798s    success guest/process_cmp:0.0.3
2020-12-30 03:07:23 0950037862e740e290037862e760e2f7 nodejs:10 warm  15.118s    success guest/process_cmp:0.0.3
2020-12-30 03:07:23 a8353280c3994a51b53280c399fa5109 nodejs:10 cold  192ms      success guest/splitter:0.0.2
2020-12-30 03:07:22 84c54a91cd9d4c37854a91cd9dec3715 nodejs:10 warm  19ms       success guest/process_cmp:0.0.3
2020-12-30 03:07:21 302fa70cea504175afa70cea5011758e nodejs:10 cold  596ms      success guest/generator:0.0.2
2020-12-30 03:07:19 cc4034d93d9346988034d93d938698ed nodejs:10 cold  589ms      success guest/process_cmp:0.0.3
2020-12-30 03:07:18 154a0556e70b4b0e8a0556e70b7b0eb2 sequence  warm  21.701s    success guest/process_cmp:0.0.3

Problem

Invoking actions deployed with a concurrency limit greater than 1 brings the openwhisk-composer to use echo action to retrieve intermediate result from redis node.

In both cases the composition result is calculated correctly.

The disadvantage is that trying to enable concurrency to have lower latency, the execution time is penalized by:

• conductor actions which are forced (for some reason) to wait for a timeout to expire;
• cold starts introduced by a further call to the echo action.

[singhsegv]

I am also facing something similar, in case of fan-in pattern my autogenerated conductor action waits till the last 30 second of whatever timeout I set to actually be called. Did you face any similar issue?