Arvados

This create request has "duration":350.31,"view":0.34,"db":116.21.

This seems a little excessive. Increasing the number of submissions in flight might jam up the database without a significant impact on throughput.

Based on logs alone I can't account for all that latency.

{
  "method": "POST",
  "path": "/arvados/v1/container_requests",
  "format": "json",
  "controller": "Arvados::V1::ContainerRequestsController",
  "action": "create",
  "status": 200,
  "duration": 350.31,
  "view": 0.34,
  "db": 116.21,
  "request_id": "req-hc9pcexvfftojkmv4j70",
  "client_ipaddr": "172.17.0.1",
  "client_auth": "2tlax-gj3su-sq60vfd0xzi13wh",
  "params": {
    "scheduling_parameters": {},
    "runtime_constraints": {
      "vcpus": 1,
      "ram": 1073741824
    },
    "use_existing": true,
    "secret_mounts": {},
    "mounts": {
      "/tmp": {
        "kind": "tmp",
        "capacity": 1073741824
      },
      "/var/spool/cwl": {
        "kind": "tmp",
        "capacity": 1073741824
      }
    },
    "owner_uuid": null,
    "properties": {},
    "output_ttl": 0,
    "environment": {
      "HOME": "/var/spool/cwl",
      "TMPDIR": "/tmp" 
    },
    "name": "step2_4",
    "priority": 500,
    "state": "Committed",
    "command": [
      "/bin/sh",
      "-c",
      "echo starting && sleep 194 && echo the number of the day is 4" 
    ],
    "container_image": "arvados/jobs",
    "output_path": "/var/spool/cwl",
    "cwd": "/var/spool/cwl",
    "alt": "json",
    "container_request": {
      "owner_uuid": null,
      "name": "step2_4",
      "properties": {},
      "state": "Committed",
      "mounts": {
        "/tmp": {
          "kind": "tmp",
          "capacity": 1073741824
        },
        "/var/spool/cwl": {
          "kind": "tmp",
          "capacity": 1073741824
        }
      },
      "runtime_constraints": {
        "vcpus": 1,
        "ram": 1073741824
      },
      "container_image": "arvados/jobs",
      "environment": {
        "HOME": "/var/spool/cwl",
        "TMPDIR": "/tmp" 
      },
      "cwd": "/var/spool/cwl",
      "command": [
        "/bin/sh",
        "-c",
        "echo starting && sleep 194 && echo the number of the day is 4" 
      ],
      "output_path": "/var/spool/cwl",
      "priority": 500,
      "use_existing": true,
      "scheduling_parameters": {},
      "output_ttl": 0
    }
  },
  "@timestamp": "2018-04-02T20:26:45.095963550Z",
  "@version": "1",
  "message": "[200] POST /arvados/v1/container_requests (Arvados::V1::ContainerRequestsController#create)" 
}

• Adding concurrency to arvados-cwl-runner is necessary to support large workflows efficiently, no matter how fast we make the "create container request" operation. (When API server is working well, request turnaround time is limited by network latency and single-threaded Ruby code.)
• Limiting concurrency to 1 in each arvados-cwl-runner process is not an effective way to avoid overloading an API server with more requests than it can handle. This can only be addressed on the API side.
• a-c-r must behave well when API server is processing requests slowly -- whether that's because this a-c-r process is overloading API, or something else is overloading API.

Ideally API server would tell clients where to cap concurrent connections, so it could be site-configurable and/or dynamic in response to load, but a command-line option (defaulting to 1? 4? ncpus?) would be a good start.

Even now, the timing figures in note-3 suggest we spend 2x as much time in Ruby as we do waiting for the DB, which seems to mean the database won't even be busy with one query at a time until we are doing at least 3 concurrent API requests. PostgreSQL is good at concurrent queries, so I expect even that example (dev?) site can do way more than 3 efficiently.

So the main reason I started looking into it was that on my development install, with a-c-r submitting a 100-way scatter of container requests with no parallelization, with "top" I was seeing four maxed out ruby processes.

But that's probably not representative of production, and clearly we want parallel queries to overcome other sources of latency. But I thought it was notable that transactions involving container requests take 3x-6x as long as transactions involving collections (for example).

I'll get started on parallel requests.

Notes to self:

• Need to use ThreadSafeApiCache
• Spin off ArvadosContainer.run() into its own thread (or queue or threadpool)
• Need to keep a "pending" counter of requests in flight, decrement when container uuid is entered into process table (add methods to ArvCwlRunner instead of changing processes directly)
• SecretStore is not threadsafe but it doesn't matter, secrets are only entered during initialization, after that it is read only
• CollectionFsAccess should be threadsafe via CollectionCache
• Need to take workflow evaluation lock (ArvCwlRunner.cond) around output_callback
• arv_docker_get_image needs to be support concurrent invocation without stepping on itself

13108-cwl-parallel-submit @ 091c2bc58ff1a8d1c43abf0e334837d8872b914d

https://ci.curoverse.com/job/developer-run-tests/681/

Here're some comments/questions:

• File sdk/python/arvados/commands/keepdocker.py:
  • Lines 425-429: For the sake of having less lines of code, could we say something like parent_project_uuid = args.project_uuid or api.users().current().execute(…) ?
• File sdk/cwl/arvados_cwl/__init__.py:
  • Lines 168, 169: I think we could save 1 indentation level by putting all those conditionals on a single if statement
  • Lines 181, 182: Should those be inside the with: block? If not, why is it necessary to use a lock to just get a value from a dict?
  • Line 389: Why passing thread_count through cwltool/arv_executor instead of just using it at ArvCwlRunner instantiation?
  • Line 554: Small typo ‘pendingjobs’ on log message
• Would it be convenient to write some tests for TaskQueue? It’s written as it would be useful to other modules as needed, so I think it would be nice to guarantee that’s working as expected.
• File sdk/cwl/arvados_cwl/task_queue.py:
  • Line 45: Should task() be inside a try: except: block?
  • Line 51: I think that task_queue.empty() check is unnecessary, get() will still raise a Queue.Empty exception when it should.

Lucas Di Pentima wrote:

Here're some comments/questions:

• File sdk/python/arvados/commands/keepdocker.py:
  • Lines 425-429: For the sake of having less lines of code, could we say something like parent_project_uuid = args.project_uuid or api.users().current().execute(…) ?

Done.

• File sdk/cwl/arvados_cwl/__init__.py:
  • Lines 168, 169: I think we could save 1 indentation level by putting all those conditionals on a single if statement

Done.

• Lines 181, 182: Should those be inside the with: block? If not, why is it necessary to use a lock to just get a value from a dict?

The other lines don't need to be in the with: block. You're right it isn't technically necessary to get a lock to get a value from a dict, however updating the processes dict can occur together in the same critical section as other operations so it is better to be on the safe side.

• Line 389: Why passing thread_count through cwltool/arv_executor instead of just using it at ArvCwlRunner instantiation?

You're right, that's better. Done.

• Line 554: Small typo ‘pendingjobs’ on log message

Fixed.

• Would it be convenient to write some tests for TaskQueue? It’s written as it would be useful to other modules as needed, so I think it would be nice to guarantee that’s working as expected.

I added a couple of simple tests.

• File sdk/cwl/arvados_cwl/task_queue.py:
  • Line 45: Should task() be inside a try: except: block?

No. When task() is called synchronously, if there is an unhandled exception, it should go to the caller.

• Line 51: I think that task_queue.empty() check is unnecessary, get() will still raise a Queue.Empty exception when it should.

No, when Queue.get() is called without block=False or a timeout, it won't raise an Empty() exception. However, it also seems that calling get() will raise the Empty exception in any case that it can't get the queue lock, not just when the queue is actually empty, so getting the Empty exception doesn't guarantee that the queue is really empty. So we still want to explicitly check if it is empty.

However it is also possible that something could sweep in a grab the last item between checking empty() calling get() so I added a timeout.

13108-cwl-parallel-submit @ 138fef8ee97f3cbd335434ad6acd26771fd0b762

This LGTM. Thanks!

13108-acr-threading-fixes @ 19da21ab8e56154d7db15c2643524cb8348a7a8a

• crunch_script.py initializes ArvCwlRunner with ThreadSafeApiCache
• Fix "Runner.done" method to use arvrunner.process_done (which has correct locking)
• ArvadosJob.update_pipeline_component takes lock to avoid update races
• Don't try to install signal handler on background when invoking arv-put via arv-keepdocker
• Do install signal handler in main thread to convert SIGTERM into KeyboardInterrupt

https://ci.curoverse.com/job/developer-run-tests/685/

This LGTM, the only detail that may or may not be an issue is that arv-put logs a stack trace when receiving signals and it assumes that KeyboardInterrupt is "translated" to SystemExit (put.py lines 576-588)

Lucas Di Pentima wrote:

This LGTM, the only detail that may or may not be an issue is that arv-put logs a stack trace when receiving signals and it assumes that KeyboardInterrupt is "translated" to SystemExit (put.py lines 576-588)

I refactored things a bit, so arv-put and a-c-r use the same code to install the signal handler.

13108-acr-threading-fixes @ 8e3adbcf390deaffed7f2449056959252e1a49f4

https://ci.curoverse.com/job/developer-run-tests/686/

This LGTM, thanks!

20-way scatter

100-way scatter

note: about 6s of that is the workflow engine constructing each scatter job. This isn't parallelized, only the submission to Arvados.