search

vhive-serverless / vHive

vHive: Open-source framework for serverless experimentation
MIT License
274 stars 86 forks source link

Nothing generated from vHive profiling tool #498

Closed dhuang-esl closed 1 year ago

dhuang-esl commented 2 years ago

Describe the bug I run the vHive profiling tool following this tutorial. However the profile.csv is not generated. I think the profiling step has been skipped somehow. Please refer to the following log section.

To Reproduce On a Cloudlab node:

git clone https://github.com/ease-lab/vhive.git
cd vhive
then following the profiling tutorial to launch the experiment

Logs

~/vhive$ sudo env "PATH=$PATH" go test -v -timeout 99999s -run TestProfileSingleConfiguration -args -funcNames helloworld -vm 1 -rps 20 -l 1
INFO[2022-03-09T07:03:02.582939321-07:00] Orchestrator snapshots enabled: false
INFO[2022-03-09T07:03:02.583035286-07:00] Orchestrator UPF enabled: false
INFO[2022-03-09T07:03:02.583058286-07:00] Orchestrator lazy serving mode enabled: false
INFO[2022-03-09T07:03:02.583068413-07:00] Orchestrator UPF metrics enabled: false
INFO[2022-03-09T07:03:02.583080771-07:00] Drop cache: true
INFO[2022-03-09T07:03:02.583095482-07:00] Bench dir: bench_results
INFO[2022-03-09T07:03:02.583108479-07:00] Registering bridges for tap manager
INFO[2022-03-09T07:03:02.584695283-07:00] Creating containerd client
INFO[2022-03-09T07:03:02.585429969-07:00] Created containerd client
INFO[2022-03-09T07:03:02.585449706-07:00] Creating firecracker client
INFO[2022-03-09T07:03:02.585535175-07:00] Created firecracker client
=== RUN   TestProfileSingleConfiguration
    perf_bench_test.go:137: Skipping TestProfileSingleConfiguration
--- SKIP: TestProfileSingleConfiguration (0.00s)
PASS
INFO[2022-03-09T07:03:02.585725163-07:00] waiting for goroutines
INFO[2022-03-09T07:03:02.585740391-07:00] waiting done
INFO[2022-03-09T07:03:02.585749372-07:00] Closing fcClient
INFO[2022-03-09T07:03:02.585760299-07:00] Closing containerd client
INFO[2022-03-09T07:03:02.585778188-07:00] Removing bridges
ok      github.com/ease-lab/vhive       0.234s

Solution Line 137 of perf_bench_test.go should be commented out, according to: https://github.com/ease-lab/vSwarm/issues/60

niravnshah commented 1 year ago

Along with line 137, we also need to comment out line 89 for TestProfileIncrementConfiguration in perf_bench_test.go

niravnshah commented 1 year ago

Even after commenting those skip lines, I am not able to successfully get the profile.csv. The test seems to be running, but hitting some error. Here is the output.

nshah5@d8eb97bf800a:~/vhive$ sudo env "PATH=$PATH" go test -v -timeout 99999s -run TestProfileSingleConfiguration -args -funcNames helloworld -vm 1 -rps 20 -l 1
INFO[2022-09-14T05:10:04.258264991-07:00] Orchestrator snapshots enabled: false
INFO[2022-09-14T05:10:04.258293066-07:00] Orchestrator UPF enabled: false
INFO[2022-09-14T05:10:04.258295382-07:00] Orchestrator lazy serving mode enabled: false
INFO[2022-09-14T05:10:04.258298402-07:00] Orchestrator UPF metrics enabled: false
INFO[2022-09-14T05:10:04.258300842-07:00] Drop cache: true
INFO[2022-09-14T05:10:04.258302514-07:00] Bench dir: bench_results
INFO[2022-09-14T05:10:04.258305787-07:00] Registering bridges for tap manager
INFO[2022-09-14T05:10:04.258691808-07:00] Creating containerd client
INFO[2022-09-14T05:10:04.259101147-07:00] Created containerd client
INFO[2022-09-14T05:10:04.259111889-07:00] Creating firecracker client
INFO[2022-09-14T05:10:04.259148340-07:00] Created firecracker client
=== RUN   TestProfileSingleConfiguration
INFO[2022-09-14T05:10:04.279944728-07:00] New function added                            fID=0 image="ghcr.io/ease-lab/helloworld:var_workload" isPinned=true servedTh=0
WARN[2022-09-14T05:10:14.961628442-07:00] Failed to Fetch k8s dns clusterIP exit status 1
The connection to the server localhost:8080 was refused - did you specify the right host or port?

WARN[2022-09-14T05:10:14.961698675-07:00] Using google dns 8.8.8.8
INFO[2022-09-14T05:10:16.323309057-07:00] Current RPS: 1
WARN[2022-09-14T05:10:16.323502626-07:00] Too many latency samples for 1 VM, measure 20 samples instead.
    perf_bench_test.go:389:
                Error Trace:    /home/nshah5/vhive/perf_bench_test.go:389
                                                        /home/nshah5/vhive/perf_bench_test.go:156
                Error:          Received unexpected error:
                                open profile.csv: no such file or directory
                Test:           TestProfileSingleConfiguration
                Messages:       Stopping profiler returned error: open profile.csv: no such file or directory
--- FAIL: TestProfileSingleConfiguration (33.07s)
FAIL
INFO[2022-09-14T05:10:37.332548089-07:00] waiting for goroutines
INFO[2022-09-14T05:10:48.454285811-07:00] waiting done
INFO[2022-09-14T05:10:48.454354293-07:00] Closing fcClient
INFO[2022-09-14T05:10:48.454375738-07:00] Closing containerd client
INFO[2022-09-14T05:10:48.454403853-07:00] Removing bridges
exit status 1
FAIL    github.com/ease-lab/vhive       44.335s

Here is the output from the containerd deamon

nshah5@d8eb97bf800a:~/vhive$ sudo PATH=$PATH /usr/local/bin/firecracker-containerd --config /etc/firecracker-containerd/config.toml
WARN[0000] deprecated version : `1`, please switch to version `2`
INFO[2022-09-14T05:08:21.427531277-07:00] starting containerd                           revision=4a8adae2660e3db2ea9b5b7b057b4388b9f5bab8 version=1.5.2+unknown
INFO[2022-09-14T05:08:21.457246061-07:00] loading plugin "io.containerd.content.v1.content"...  type=io.containerd.content.v1
INFO[2022-09-14T05:08:21.457490072-07:00] loading plugin "io.containerd.snapshotter.v1.devmapper"...  type=io.containerd.snapshotter.v1
INFO[2022-09-14T05:08:21.457571524-07:00] initializing pool device "fc-dev-thinpool"
INFO[2022-09-14T05:08:21.460579690-07:00] using dmsetup:
Library version:   1.02.167 (2019-11-30)
Driver version:    4.41.0
INFO[2022-09-14T05:08:21.489601827-07:00] loading plugin "io.containerd.snapshotter.v1.overlayfs"...  type=io.containerd.snapshotter.v1
INFO[2022-09-14T05:08:21.490340087-07:00] loading plugin "io.containerd.metadata.v1.bolt"...  type=io.containerd.metadata.v1
INFO[2022-09-14T05:08:21.490460619-07:00] metadata content store policy set             policy=shared
INFO[2022-09-14T05:08:21.509246979-07:00] loading plugin "io.containerd.differ.v1.walking"...  type=io.containerd.differ.v1
INFO[2022-09-14T05:08:21.509320135-07:00] loading plugin "io.containerd.gc.v1.scheduler"...  type=io.containerd.gc.v1
INFO[2022-09-14T05:08:21.509382117-07:00] loading plugin "io.containerd.service.v1.introspection-service"...  type=io.containerd.service.v1
INFO[2022-09-14T05:08:21.509423345-07:00] loading plugin "io.containerd.service.v1.containers-service"...  type=io.containerd.service.v1
INFO[2022-09-14T05:08:21.509450959-07:00] loading plugin "io.containerd.service.v1.content-service"...  type=io.containerd.service.v1
INFO[2022-09-14T05:08:21.509476187-07:00] loading plugin "io.containerd.service.v1.diff-service"...  type=io.containerd.service.v1
INFO[2022-09-14T05:08:21.509501371-07:00] loading plugin "io.containerd.service.v1.images-service"...  type=io.containerd.service.v1
INFO[2022-09-14T05:08:21.509527977-07:00] loading plugin "io.containerd.service.v1.leases-service"...  type=io.containerd.service.v1
INFO[2022-09-14T05:08:21.509554624-07:00] loading plugin "io.containerd.service.v1.namespaces-service"...  type=io.containerd.service.v1
INFO[2022-09-14T05:08:21.509580164-07:00] loading plugin "io.containerd.service.v1.snapshots-service"...  type=io.containerd.service.v1
INFO[2022-09-14T05:08:21.509603409-07:00] loading plugin "io.containerd.runtime.v1.linux"...  type=io.containerd.runtime.v1
INFO[2022-09-14T05:08:21.509776927-07:00] loading plugin "io.containerd.runtime.v2.task"...  type=io.containerd.runtime.v2
INFO[2022-09-14T05:08:21.509904834-07:00] loading plugin "io.containerd.monitor.v1.cgroups"...  type=io.containerd.monitor.v1
INFO[2022-09-14T05:08:21.510822964-07:00] loading plugin "io.containerd.service.v1.tasks-service"...  type=io.containerd.service.v1
INFO[2022-09-14T05:08:21.510952811-07:00] loading plugin "io.containerd.service.v1.fc-control"...  type=io.containerd.service.v1
DEBU[2022-09-14T05:08:21.510991579-07:00] initializing fc-control plugin (root: "/var/lib/firecracker-containerd/containerd/io.containerd.service.v1.fc-control")
INFO[2022-09-14T05:08:21.511733541-07:00] loading plugin "io.containerd.internal.v1.restart"...  type=io.containerd.internal.v1
INFO[2022-09-14T05:08:21.511865116-07:00] loading plugin "io.containerd.grpc.v1.containers"...  type=io.containerd.grpc.v1
INFO[2022-09-14T05:08:21.511905614-07:00] loading plugin "io.containerd.grpc.v1.content"...  type=io.containerd.grpc.v1
INFO[2022-09-14T05:08:21.511939589-07:00] loading plugin "io.containerd.grpc.v1.diff"...  type=io.containerd.grpc.v1
INFO[2022-09-14T05:08:21.511970781-07:00] loading plugin "io.containerd.grpc.v1.events"...  type=io.containerd.grpc.v1
INFO[2022-09-14T05:08:21.512004404-07:00] loading plugin "io.containerd.grpc.v1.healthcheck"...  type=io.containerd.grpc.v1
INFO[2022-09-14T05:08:21.512039559-07:00] loading plugin "io.containerd.grpc.v1.images"...  type=io.containerd.grpc.v1
INFO[2022-09-14T05:08:21.512070767-07:00] loading plugin "io.containerd.grpc.v1.leases"...  type=io.containerd.grpc.v1
INFO[2022-09-14T05:08:21.512103377-07:00] loading plugin "io.containerd.grpc.v1.namespaces"...  type=io.containerd.grpc.v1
INFO[2022-09-14T05:08:21.512138579-07:00] loading plugin "io.containerd.internal.v1.opt"...  type=io.containerd.internal.v1
INFO[2022-09-14T05:08:21.512231447-07:00] loading plugin "io.containerd.grpc.v1.snapshots"...  type=io.containerd.grpc.v1
INFO[2022-09-14T05:08:21.512271462-07:00] loading plugin "io.containerd.grpc.v1.tasks"...  type=io.containerd.grpc.v1
INFO[2022-09-14T05:08:21.512317242-07:00] loading plugin "io.containerd.grpc.v1.version"...  type=io.containerd.grpc.v1
INFO[2022-09-14T05:08:21.512350249-07:00] loading plugin "io.containerd.grpc.v1.fc-control-service"...  type=io.containerd.grpc.v1
DEBU[2022-09-14T05:08:21.512374808-07:00] initializing fc-control-service plugin
INFO[2022-09-14T05:08:21.512405867-07:00] loading plugin "io.containerd.grpc.v1.introspection"...  type=io.containerd.grpc.v1
INFO[2022-09-14T05:08:21.512707290-07:00] serving...                                    address=/run/firecracker-containerd/containerd.sock.ttrpc
INFO[2022-09-14T05:08:21.512806566-07:00] serving...                                    address=/run/firecracker-containerd/containerd.sock
DEBU[2022-09-14T05:08:21.512841655-07:00] sd notification                               error="<nil>" notified=false state="READY=1"
INFO[2022-09-14T05:08:21.512878342-07:00] containerd successfully booted in 0.087852s
DEBU[2022-09-14T05:08:21.617526508-07:00] garbage collected                             d=7.598209ms
DEBU[2022-09-14T05:10:04.776809914-07:00] (*service).Write started                      expected="sha256:12dc6715ed1a8306f246ceaf7742c09e38a52a79d17421e4a50d7e0e09fdbc25" ref="manifest-sha256:12dc6715ed1a8306f246ceaf7742c09e38a52a79d17421e4a50d7e0e09fdbc25" total=1998
DEBU[2022-09-14T05:10:04.990809470-07:00] (*service).Write started                      expected="sha256:a87533385b75fd1d476d8a1112a0c5db953e3d5b44d4f9db814b1e2e6abb8734" ref="config-sha256:a87533385b75fd1d476d8a1112a0c5db953e3d5b44d4f9db814b1e2e6abb8734" total=8312
DEBU[2022-09-14T05:10:05.290185113-07:00] stat snapshot                                 key="sha256:5216338b40a7b96416b8b9858974bbe4acc3096ee60acbc4dfb1ee02aecceb10"
DEBU[2022-09-14T05:10:05.292295594-07:00] prepare snapshot                              key="extract-291643355-Xw-a sha256:5216338b40a7b96416b8b9858974bbe4acc3096ee60acbc4dfb1ee02aecceb10" parent=
DEBU[2022-09-14T05:10:05.295280363-07:00] prepare                                       key="firecracker-containerd/1/extract-291643355-Xw-a sha256:5216338b40a7b96416b8b9858974bbe4acc3096ee60acbc4dfb1ee02aecceb10" parent=
DEBU[2022-09-14T05:10:05.300770274-07:00] creating new thin device 'fc-dev-thinpool-snap-1'
DEBU[2022-09-14T05:10:05.411196459-07:00] mkfs.ext4 -E nodiscard,lazy_itable_init=0,lazy_journal_init=0 /dev/mapper/fc-dev-thinpool-snap-1
DEBU[2022-09-14T05:10:05.708144681-07:00] mkfs:
mke2fs 1.45.5 (07-Jan-2020)
Creating filesystem with 2621440 4k blocks and 655360 inodes
Filesystem UUID: 29012b3e-befe-45ef-aa41-a62ea9a5d036
Superblock backups stored on blocks:
        32768, 98304, 163840, 229376, 294912, 819200, 884736, 1605632

Allocating group tables: done
Writing inode tables: done
Creating journal (16384 blocks): done
Writing superblocks and filesystem accounting information: done

DEBU[2022-09-14T05:10:05.774787839-07:00] event published                               ns=firecracker-containerd topic=/snapshot/prepare type=containerd.events.SnapshotPrepare
DEBU[2022-09-14T05:10:05.776058288-07:00] (*service).Write started                      expected="sha256:407da27a03363f6b9d368ec6e131f7f2db7c8cb2a149160d913d6f3698905a5d" ref="layer-sha256:407da27a03363f6b9d368ec6e131f7f2db7c8cb2a149160d913d6f3698905a5d" total=1887472
DEBU[2022-09-14T05:10:05.776078249-07:00] (*service).Write started                      expected="sha256:c09d5cdb7367fff0d581bb8003e3520dc3e8bd78811dfb51c92df81e58c3a50d" ref="layer-sha256:c09d5cdb7367fff0d581bb8003e3520dc3e8bd78811dfb51c92df81e58c3a50d" total=637463
DEBU[2022-09-14T05:10:05.776132929-07:00] (*service).Write started                      expected="sha256:92b614cff45fafd028cec952e0cb2584e8d931bf0321e7d14bfafdf7a50ac3fa" ref="layer-sha256:92b614cff45fafd028cec952e0cb2584e8d931bf0321e7d14bfafdf7a50ac3fa" total=2233
DEBU[2022-09-14T05:10:05.776195371-07:00] (*service).Write started                      expected="sha256:61614c1a5710c76af6b2a9c7170a81eb0dd76ccf90e921abc0c9dcc1d5ed490e" ref="layer-sha256:61614c1a5710c76af6b2a9c7170a81eb0dd76ccf90e921abc0c9dcc1d5ed490e" total=31506523
DEBU[2022-09-14T05:10:05.776312427-07:00] (*service).Write started                      expected="sha256:c9b1b535fdd91a9855fb7f82348177e5f019329a58c53c47272962dd60f71fc9" ref="layer-sha256:c9b1b535fdd91a9855fb7f82348177e5f019329a58c53c47272962dd60f71fc9" total=2802957
DEBU[2022-09-14T05:10:05.776345136-07:00] (*service).Write started                      expected="sha256:0522d30cde10ac29ae2c555b9bde76c2b50aafc7ef7435bbc7e19de706bcadcd" ref="layer-sha256:0522d30cde10ac29ae2c555b9bde76c2b50aafc7ef7435bbc7e19de706bcadcd" total=230
DEBU[2022-09-14T05:10:05.776374956-07:00] (*service).Write started                      expected="sha256:0d776ee02572ee50935002da7bd7fcda4a60be4a48c4ace5dd3216c327e6767a" ref="layer-sha256:0d776ee02572ee50935002da7bd7fcda4a60be4a48c4ace5dd3216c327e6767a" total=20365161
DEBU[2022-09-14T05:10:05.776344802-07:00] (*service).Write started                      expected="sha256:2cc5ad85d9abaadf23d5ae53c3f32e7ccb2df1956869980bfd2491ff396d348a" ref="layer-sha256:2cc5ad85d9abaadf23d5ae53c3f32e7ccb2df1956869980bfd2491ff396d348a" total=301261
DEBU[2022-09-14T05:10:06.582939405-07:00] unpigz not found, falling back to go gzip     error="exec: \"unpigz\": executable file not found in $PATH"
DEBU[2022-09-14T05:10:06.774918043-07:00] diff applied                                  d=192.183229ms digest="sha256:c9b1b535fdd91a9855fb7f82348177e5f019329a58c53c47272962dd60f71fc9" media=application/vnd.docker.image.rootfs.diff.tar.gzip size=2802957
DEBU[2022-09-14T05:10:06.775482692-07:00] commit snapshot                               key="extract-291643355-Xw-a sha256:5216338b40a7b96416b8b9858974bbe4acc3096ee60acbc4dfb1ee02aecceb10" name="sha256:5216338b40a7b96416b8b9858974bbe4acc3096ee60acbc4dfb1ee02aecceb10"
DEBU[2022-09-14T05:10:06.775742585-07:00] commit                                        key="firecracker-containerd/1/extract-291643355-Xw-a sha256:5216338b40a7b96416b8b9858974bbe4acc3096ee60acbc4dfb1ee02aecceb10" name="firecracker-containerd/2/sha256:5216338b40a7b96416b8b9858974bbe4acc3096ee60acbc4dfb1ee02aecceb10"
DEBU[2022-09-14T05:10:06.936433506-07:00] event published                               ns=firecracker-containerd topic=/snapshot/commit type=containerd.events.SnapshotCommit
DEBU[2022-09-14T05:10:06.940996986-07:00] stat snapshot                                 key="sha256:5edfa66f961ecdadabac1b15441c567a06631fd4cb8a197a2f0399644a3c18d5"
DEBU[2022-09-14T05:10:06.941461403-07:00] prepare snapshot                              key="extract-941242333-Yh1y sha256:5edfa66f961ecdadabac1b15441c567a06631fd4cb8a197a2f0399644a3c18d5" parent="sha256:5216338b40a7b96416b8b9858974bbe4acc3096ee60acbc4dfb1ee02aecceb10"
DEBU[2022-09-14T05:10:06.944550870-07:00] prepare                                       key="firecracker-containerd/3/extract-941242333-Yh1y sha256:5edfa66f961ecdadabac1b15441c567a06631fd4cb8a197a2f0399644a3c18d5" parent="firecracker-containerd/2/sha256:5216338b40a7b96416b8b9858974bbe4acc3096ee60acbc4dfb1ee02aecceb10"
DEBU[2022-09-14T05:10:06.944676536-07:00] creating snapshot device 'fc-dev-thinpool-snap-2' from 'fc-dev-thinpool-snap-1'
DEBU[2022-09-14T05:10:07.115540042-07:00] event published                               ns=firecracker-containerd topic=/snapshot/prepare type=containerd.events.SnapshotPrepare
DEBU[2022-09-14T05:10:07.286244989-07:00] diff applied                                  d=170.135497ms digest="sha256:2cc5ad85d9abaadf23d5ae53c3f32e7ccb2df1956869980bfd2491ff396d348a" media=application/vnd.docker.image.rootfs.diff.tar.gzip size=301261
DEBU[2022-09-14T05:10:07.286851647-07:00] commit snapshot                               key="extract-941242333-Yh1y sha256:5edfa66f961ecdadabac1b15441c567a06631fd4cb8a197a2f0399644a3c18d5" name="sha256:5edfa66f961ecdadabac1b15441c567a06631fd4cb8a197a2f0399644a3c18d5"
DEBU[2022-09-14T05:10:07.287164080-07:00] commit                                        key="firecracker-containerd/3/extract-941242333-Yh1y sha256:5edfa66f961ecdadabac1b15441c567a06631fd4cb8a197a2f0399644a3c18d5" name="firecracker-containerd/4/sha256:5edfa66f961ecdadabac1b15441c567a06631fd4cb8a197a2f0399644a3c18d5"
DEBU[2022-09-14T05:10:07.428237494-07:00] event published                               ns=firecracker-containerd topic=/snapshot/commit type=containerd.events.SnapshotCommit
DEBU[2022-09-14T05:10:07.432132497-07:00] stat snapshot                                 key="sha256:483d3bedbf62615f629bcfd167c0f2b45df7afe3ecb6b3f7ffa7ebe2dab70faa"
DEBU[2022-09-14T05:10:07.432836382-07:00] prepare snapshot                              key="extract-432480937-lWbH sha256:483d3bedbf62615f629bcfd167c0f2b45df7afe3ecb6b3f7ffa7ebe2dab70faa" parent="sha256:5edfa66f961ecdadabac1b15441c567a06631fd4cb8a197a2f0399644a3c18d5"
DEBU[2022-09-14T05:10:07.435979583-07:00] prepare                                       key="firecracker-containerd/5/extract-432480937-lWbH sha256:483d3bedbf62615f629bcfd167c0f2b45df7afe3ecb6b3f7ffa7ebe2dab70faa" parent="firecracker-containerd/4/sha256:5edfa66f961ecdadabac1b15441c567a06631fd4cb8a197a2f0399644a3c18d5"
DEBU[2022-09-14T05:10:07.436115525-07:00] creating snapshot device 'fc-dev-thinpool-snap-3' from 'fc-dev-thinpool-snap-2'
DEBU[2022-09-14T05:10:07.604121655-07:00] event published                               ns=firecracker-containerd topic=/snapshot/prepare type=containerd.events.SnapshotPrepare
DEBU[2022-09-14T05:10:11.934710552-07:00] diff applied                                  d=911.597693ms digest="sha256:61614c1a5710c76af6b2a9c7170a81eb0dd76ccf90e921abc0c9dcc1d5ed490e" media=application/vnd.docker.image.rootfs.diff.tar.gzip size=31506523
DEBU[2022-09-14T05:10:11.935469440-07:00] commit snapshot                               key="extract-432480937-lWbH sha256:483d3bedbf62615f629bcfd167c0f2b45df7afe3ecb6b3f7ffa7ebe2dab70faa" name="sha256:483d3bedbf62615f629bcfd167c0f2b45df7afe3ecb6b3f7ffa7ebe2dab70faa"
DEBU[2022-09-14T05:10:11.935792065-07:00] commit                                        key="firecracker-containerd/5/extract-432480937-lWbH sha256:483d3bedbf62615f629bcfd167c0f2b45df7afe3ecb6b3f7ffa7ebe2dab70faa" name="firecracker-containerd/6/sha256:483d3bedbf62615f629bcfd167c0f2b45df7afe3ecb6b3f7ffa7ebe2dab70faa"
DEBU[2022-09-14T05:10:12.081357487-07:00] event published                               ns=firecracker-containerd topic=/snapshot/commit type=containerd.events.SnapshotCommit
DEBU[2022-09-14T05:10:12.085877782-07:00] stat snapshot                                 key="sha256:3adc9ed0c3e4c8e4fb839cc55b92b0fefb26459b3d03edcbe139e0bd097fca0f"
DEBU[2022-09-14T05:10:12.086644490-07:00] prepare snapshot                              key="extract-86329206-TRAD sha256:3adc9ed0c3e4c8e4fb839cc55b92b0fefb26459b3d03edcbe139e0bd097fca0f" parent="sha256:483d3bedbf62615f629bcfd167c0f2b45df7afe3ecb6b3f7ffa7ebe2dab70faa"
DEBU[2022-09-14T05:10:12.089992158-07:00] prepare                                       key="firecracker-containerd/7/extract-86329206-TRAD sha256:3adc9ed0c3e4c8e4fb839cc55b92b0fefb26459b3d03edcbe139e0bd097fca0f" parent="firecracker-containerd/6/sha256:483d3bedbf62615f629bcfd167c0f2b45df7afe3ecb6b3f7ffa7ebe2dab70faa"
DEBU[2022-09-14T05:10:12.090144866-07:00] creating snapshot device 'fc-dev-thinpool-snap-4' from 'fc-dev-thinpool-snap-3'
DEBU[2022-09-14T05:10:12.260212648-07:00] event published                               ns=firecracker-containerd topic=/snapshot/prepare type=containerd.events.SnapshotPrepare
DEBU[2022-09-14T05:10:12.350458282-07:00] diff applied                                  d=89.543767ms digest="sha256:0522d30cde10ac29ae2c555b9bde76c2b50aafc7ef7435bbc7e19de706bcadcd" media=application/vnd.docker.image.rootfs.diff.tar.gzip size=230
DEBU[2022-09-14T05:10:12.351140681-07:00] commit snapshot                               key="extract-86329206-TRAD sha256:3adc9ed0c3e4c8e4fb839cc55b92b0fefb26459b3d03edcbe139e0bd097fca0f" name="sha256:3adc9ed0c3e4c8e4fb839cc55b92b0fefb26459b3d03edcbe139e0bd097fca0f"
DEBU[2022-09-14T05:10:12.351391610-07:00] commit                                        key="firecracker-containerd/7/extract-86329206-TRAD sha256:3adc9ed0c3e4c8e4fb839cc55b92b0fefb26459b3d03edcbe139e0bd097fca0f" name="firecracker-containerd/8/sha256:3adc9ed0c3e4c8e4fb839cc55b92b0fefb26459b3d03edcbe139e0bd097fca0f"
DEBU[2022-09-14T05:10:12.516986589-07:00] event published                               ns=firecracker-containerd topic=/snapshot/commit type=containerd.events.SnapshotCommit
DEBU[2022-09-14T05:10:12.521489957-07:00] stat snapshot                                 key="sha256:7893763263404b202f7a20649fdab037cf7200d38d5a5e6fc35ced2c072df270"
DEBU[2022-09-14T05:10:12.522180229-07:00] prepare snapshot                              key="extract-521790249-fE17 sha256:7893763263404b202f7a20649fdab037cf7200d38d5a5e6fc35ced2c072df270" parent="sha256:3adc9ed0c3e4c8e4fb839cc55b92b0fefb26459b3d03edcbe139e0bd097fca0f"
DEBU[2022-09-14T05:10:12.525249848-07:00] prepare                                       key="firecracker-containerd/9/extract-521790249-fE17 sha256:7893763263404b202f7a20649fdab037cf7200d38d5a5e6fc35ced2c072df270" parent="firecracker-containerd/8/sha256:3adc9ed0c3e4c8e4fb839cc55b92b0fefb26459b3d03edcbe139e0bd097fca0f"
DEBU[2022-09-14T05:10:12.525377371-07:00] creating snapshot device 'fc-dev-thinpool-snap-5' from 'fc-dev-thinpool-snap-4'
DEBU[2022-09-14T05:10:12.688272250-07:00] event published                               ns=firecracker-containerd topic=/snapshot/prepare type=containerd.events.SnapshotPrepare
DEBU[2022-09-14T05:10:12.941837082-07:00] diff applied                                  d=252.9855ms digest="sha256:407da27a03363f6b9d368ec6e131f7f2db7c8cb2a149160d913d6f3698905a5d" media=application/vnd.docker.image.rootfs.diff.tar.gzip size=1887472
DEBU[2022-09-14T05:10:12.942657349-07:00] commit snapshot                               key="extract-521790249-fE17 sha256:7893763263404b202f7a20649fdab037cf7200d38d5a5e6fc35ced2c072df270" name="sha256:7893763263404b202f7a20649fdab037cf7200d38d5a5e6fc35ced2c072df270"
DEBU[2022-09-14T05:10:12.943007720-07:00] commit                                        key="firecracker-containerd/9/extract-521790249-fE17 sha256:7893763263404b202f7a20649fdab037cf7200d38d5a5e6fc35ced2c072df270" name="firecracker-containerd/10/sha256:7893763263404b202f7a20649fdab037cf7200d38d5a5e6fc35ced2c072df270"
DEBU[2022-09-14T05:10:13.110580755-07:00] event published                               ns=firecracker-containerd topic=/snapshot/commit type=containerd.events.SnapshotCommit
DEBU[2022-09-14T05:10:13.115050735-07:00] stat snapshot                                 key="sha256:e4226272b56cdeb334d6c3377374a6760ceae26f704fddedd5ff871e52d19784"
DEBU[2022-09-14T05:10:13.115901202-07:00] prepare snapshot                              key="extract-115481254-uwQH sha256:e4226272b56cdeb334d6c3377374a6760ceae26f704fddedd5ff871e52d19784" parent="sha256:7893763263404b202f7a20649fdab037cf7200d38d5a5e6fc35ced2c072df270"
DEBU[2022-09-14T05:10:13.119123426-07:00] prepare                                       key="firecracker-containerd/11/extract-115481254-uwQH sha256:e4226272b56cdeb334d6c3377374a6760ceae26f704fddedd5ff871e52d19784" parent="firecracker-containerd/10/sha256:7893763263404b202f7a20649fdab037cf7200d38d5a5e6fc35ced2c072df270"
DEBU[2022-09-14T05:10:13.119280011-07:00] creating snapshot device 'fc-dev-thinpool-snap-6' from 'fc-dev-thinpool-snap-5'
DEBU[2022-09-14T05:10:13.272027882-07:00] event published                               ns=firecracker-containerd topic=/snapshot/prepare type=containerd.events.SnapshotPrepare
DEBU[2022-09-14T05:10:13.364199239-07:00] diff applied                                  d=91.357952ms digest="sha256:92b614cff45fafd028cec952e0cb2584e8d931bf0321e7d14bfafdf7a50ac3fa" media=application/vnd.docker.image.rootfs.diff.tar.gzip size=2233
DEBU[2022-09-14T05:10:13.364986506-07:00] commit snapshot                               key="extract-115481254-uwQH sha256:e4226272b56cdeb334d6c3377374a6760ceae26f704fddedd5ff871e52d19784" name="sha256:e4226272b56cdeb334d6c3377374a6760ceae26f704fddedd5ff871e52d19784"
DEBU[2022-09-14T05:10:13.365270770-07:00] commit                                        key="firecracker-containerd/11/extract-115481254-uwQH sha256:e4226272b56cdeb334d6c3377374a6760ceae26f704fddedd5ff871e52d19784" name="firecracker-containerd/12/sha256:e4226272b56cdeb334d6c3377374a6760ceae26f704fddedd5ff871e52d19784"
DEBU[2022-09-14T05:10:13.500645318-07:00] event published                               ns=firecracker-containerd topic=/snapshot/commit type=containerd.events.SnapshotCommit
DEBU[2022-09-14T05:10:13.504665012-07:00] stat snapshot                                 key="sha256:046f313f5e6a5160dd5c71cdf40aed78bb816bce9030b7b1617dc499a623dac8"
DEBU[2022-09-14T05:10:13.505468751-07:00] prepare snapshot                              key="extract-505097727-0eLG sha256:046f313f5e6a5160dd5c71cdf40aed78bb816bce9030b7b1617dc499a623dac8" parent="sha256:e4226272b56cdeb334d6c3377374a6760ceae26f704fddedd5ff871e52d19784"
DEBU[2022-09-14T05:10:13.508698247-07:00] prepare                                       key="firecracker-containerd/13/extract-505097727-0eLG sha256:046f313f5e6a5160dd5c71cdf40aed78bb816bce9030b7b1617dc499a623dac8" parent="firecracker-containerd/12/sha256:e4226272b56cdeb334d6c3377374a6760ceae26f704fddedd5ff871e52d19784"
DEBU[2022-09-14T05:10:13.508868710-07:00] creating snapshot device 'fc-dev-thinpool-snap-7' from 'fc-dev-thinpool-snap-6'
DEBU[2022-09-14T05:10:13.680160966-07:00] event published                               ns=firecracker-containerd topic=/snapshot/prepare type=containerd.events.SnapshotPrepare
DEBU[2022-09-14T05:10:14.250321606-07:00] diff applied                                  d=569.458925ms digest="sha256:0d776ee02572ee50935002da7bd7fcda4a60be4a48c4ace5dd3216c327e6767a" media=application/vnd.docker.image.rootfs.diff.tar.gzip size=20365161
DEBU[2022-09-14T05:10:14.251142449-07:00] commit snapshot                               key="extract-505097727-0eLG sha256:046f313f5e6a5160dd5c71cdf40aed78bb816bce9030b7b1617dc499a623dac8" name="sha256:046f313f5e6a5160dd5c71cdf40aed78bb816bce9030b7b1617dc499a623dac8"
DEBU[2022-09-14T05:10:14.251437495-07:00] commit                                        key="firecracker-containerd/13/extract-505097727-0eLG sha256:046f313f5e6a5160dd5c71cdf40aed78bb816bce9030b7b1617dc499a623dac8" name="firecracker-containerd/14/sha256:046f313f5e6a5160dd5c71cdf40aed78bb816bce9030b7b1617dc499a623dac8"
DEBU[2022-09-14T05:10:14.406254841-07:00] event published                               ns=firecracker-containerd topic=/snapshot/commit type=containerd.events.SnapshotCommit
DEBU[2022-09-14T05:10:14.410518337-07:00] stat snapshot                                 key="sha256:21d1c32ff456f90efb6f819dc94981414274877bd50caee6b7866a3f65280253"
DEBU[2022-09-14T05:10:14.411277939-07:00] prepare snapshot                              key="extract-410868331-SYGF sha256:21d1c32ff456f90efb6f819dc94981414274877bd50caee6b7866a3f65280253" parent="sha256:046f313f5e6a5160dd5c71cdf40aed78bb816bce9030b7b1617dc499a623dac8"
DEBU[2022-09-14T05:10:14.414540974-07:00] prepare                                       key="firecracker-containerd/15/extract-410868331-SYGF sha256:21d1c32ff456f90efb6f819dc94981414274877bd50caee6b7866a3f65280253" parent="firecracker-containerd/14/sha256:046f313f5e6a5160dd5c71cdf40aed78bb816bce9030b7b1617dc499a623dac8"
DEBU[2022-09-14T05:10:14.414740616-07:00] creating snapshot device 'fc-dev-thinpool-snap-8' from 'fc-dev-thinpool-snap-7'
DEBU[2022-09-14T05:10:14.574923933-07:00] event published                               ns=firecracker-containerd topic=/snapshot/prepare type=containerd.events.SnapshotPrepare
DEBU[2022-09-14T05:10:14.728095243-07:00] diff applied                                  d=152.558175ms digest="sha256:c09d5cdb7367fff0d581bb8003e3520dc3e8bd78811dfb51c92df81e58c3a50d" media=application/vnd.docker.image.rootfs.diff.tar.gzip size=637463
DEBU[2022-09-14T05:10:14.728907448-07:00] commit snapshot                               key="extract-410868331-SYGF sha256:21d1c32ff456f90efb6f819dc94981414274877bd50caee6b7866a3f65280253" name="sha256:21d1c32ff456f90efb6f819dc94981414274877bd50caee6b7866a3f65280253"
DEBU[2022-09-14T05:10:14.729174902-07:00] commit                                        key="firecracker-containerd/15/extract-410868331-SYGF sha256:21d1c32ff456f90efb6f819dc94981414274877bd50caee6b7866a3f65280253" name="firecracker-containerd/16/sha256:21d1c32ff456f90efb6f819dc94981414274877bd50caee6b7866a3f65280253"
DEBU[2022-09-14T05:10:14.873267945-07:00] event published                               ns=firecracker-containerd topic=/snapshot/commit type=containerd.events.SnapshotCommit
DEBU[2022-09-14T05:10:14.881587112-07:00] create image                                  name="ghcr.io/ease-lab/helloworld:var_workload" target="sha256:12dc6715ed1a8306f246ceaf7742c09e38a52a79d17421e4a50d7e0e09fdbc25"
DEBU[2022-09-14T05:10:14.884978186-07:00] event published                               ns=firecracker-containerd topic=/images/create type=containerd.services.images.v1.ImageCreate
DEBU[2022-09-14T05:10:14.895667801-07:00] garbage collected                             d=3.31182ms
DEBU[2022-09-14T05:10:14.962819390-07:00] create VM request: VMID:"0-0" MachineCfg:<MemSizeMib:256 VcpuCount:1 > KernelArgs:"ro noapic reboot=k panic=1 pci=off nomodules systemd.log_color=false systemd.unit=firecracker.target init=/sbin/overlay-init tsc=reliable quiet 8250.nr_uarts=0 ipv6.disable=1" NetworkInterfaces:<StaticConfig:<MacAddress:"02:FC:00:00:00:00" HostDevName:"0-0_tap" IPConfig:<PrimaryAddr:"190.128.0.2/10" GatewayAddr:"190.128.0.1" Nameservers:"8.8.8.8" > > > TimeoutSeconds:100
DEBU[2022-09-14T05:10:14.962875974-07:00] using namespace: firecracker-containerd
DEBU[2022-09-14T05:10:14.963276791-07:00] starting containerd-shim-aws-firecracker      vmID=0-0
INFO[2022-09-14T05:10:15.002049041-07:00] starting signal loop                          namespace=firecracker-containerd path=/var/lib/firecracker-containerd/shim-base/firecracker-containerd/0-0 pid=2797727
INFO[2022-09-14T05:10:15.003358748-07:00] creating new VM                               runtime=aws.firecracker vmID=0-0
INFO[2022-09-14T05:10:15.003844033-07:00] Called startVMM(), setting up a VMM on firecracker.sock  runtime=aws.firecracker
INFO[2022-09-14T05:10:15.019341451-07:00] refreshMachineConfiguration: [GET /machine-config][200] getMachineConfigurationOK  &{CPUTemplate:T2 HtEnabled:0xc00050c803 MemSizeMib:0xc00050c7f8 TrackDirtyPages:false VcpuCount:0xc00050c7f0}  runtime=aws.firecracker
INFO[2022-09-14T05:10:15.020014280-07:00] PutGuestBootSource: [PUT /boot-source][204] putGuestBootSourceNoContent   runtime=aws.firecracker
INFO[2022-09-14T05:10:15.020047457-07:00] Attaching drive /var/lib/firecracker-containerd/runtime/default-rootfs.img, slot root_drive, root true.  runtime=aws.firecracker
INFO[2022-09-14T05:10:15.020801772-07:00] Attached drive /var/lib/firecracker-containerd/runtime/default-rootfs.img: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent   runtime=aws.firecracker
INFO[2022-09-14T05:10:15.020833049-07:00] Attaching drive /var/lib/firecracker-containerd/shim-base/firecracker-containerd/0-0/ctrstub0, slot MN2HE43UOVRDA, root false.  runtime=aws.firecracker
INFO[2022-09-14T05:10:15.021383954-07:00] Attached drive /var/lib/firecracker-containerd/shim-base/firecracker-containerd/0-0/ctrstub0: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent   runtime=aws.firecracker
INFO[2022-09-14T05:10:15.021412186-07:00] Attaching NIC 0-0_tap (hwaddr 02:FC:00:00:00:00) at index 1  runtime=aws.firecracker
INFO[2022-09-14T05:10:15.048779301-07:00] startInstance successful: [PUT /actions][204] createSyncActionNoContent   runtime=aws.firecracker
INFO[2022-09-14T05:10:15.048830647-07:00] calling agent                                 runtime=aws.firecracker vmID=0-0
INFO[2022-09-14T05:10:15.549484124-07:00] successfully started the VM                   runtime=aws.firecracker vmID=0-0
DEBU[2022-09-14T05:10:15.549852241-07:00] event forwarded                               ns=firecracker-containerd topic=/firecracker-vm/start type=VMStart
DEBU[2022-09-14T05:10:15.556331602-07:00] prepare snapshot                              key=0-0 parent="sha256:21d1c32ff456f90efb6f819dc94981414274877bd50caee6b7866a3f65280253"
DEBU[2022-09-14T05:10:15.559130855-07:00] prepare                                       key=firecracker-containerd/17/0-0 parent="firecracker-containerd/16/sha256:21d1c32ff456f90efb6f819dc94981414274877bd50caee6b7866a3f65280253"
DEBU[2022-09-14T05:10:15.559173696-07:00] creating snapshot device 'fc-dev-thinpool-snap-9' from 'fc-dev-thinpool-snap-8'
DEBU[2022-09-14T05:10:15.676642645-07:00] event published                               ns=firecracker-containerd topic=/snapshot/prepare type=containerd.events.SnapshotPrepare
DEBU[2022-09-14T05:10:15.680825656-07:00] get snapshot mounts                           key=0-0
DEBU[2022-09-14T05:10:15.680894257-07:00] mounts                                        key=firecracker-containerd/17/0-0
DEBU[2022-09-14T05:10:15.758304934-07:00] event published                               ns=firecracker-containerd topic=/containers/create type=containerd.events.ContainerCreate
DEBU[2022-09-14T05:10:15.763397895-07:00] get snapshot mounts                           key=0-0
DEBU[2022-09-14T05:10:15.763501625-07:00] mounts                                        key=firecracker-containerd/17/0-0
time="2022-09-14T05:10:15.819143185-07:00" level=debug msg=StartShim runtime=aws.firecracker task_id=0-0
DEBU[2022-09-14T05:10:15.821258928-07:00] create VM request: VMID:"0-0"
DEBU[2022-09-14T05:10:15.821314665-07:00] using namespace: firecracker-containerd
time="2022-09-14T05:10:15.821992862-07:00" level=info msg="successfully started shim (git commit: 4a8adae2660e3db2ea9b5b7b057b4388b9f5bab8)." runtime=aws.firecracker task_id=0-0 vmID=0-0
INFO[2022-09-14T05:10:15.825076723-07:00] PatchGuestDrive successful                    runtime=aws.firecracker
DEBU[2022-09-14T05:10:15.934864222-07:00] event forwarded                               ns=firecracker-containerd topic=/tasks/create type=containerd.events.TaskCreate
INFO[2022-09-14T05:10:15.964754964-07:00] successfully created task                     ExecID= TaskID=0-0 pid_in_vm=720 runtime=aws.firecracker vmID=0-0
DEBU[2022-09-14T05:10:15.970233250-07:00] garbage collected                             d=4.662802ms
DEBU[2022-09-14T05:10:15.975042612-07:00] event forwarded                               ns=firecracker-containerd topic=/tasks/start type=containerd.events.TaskStart
INFO[2022-09-14T05:10:37.343230958-07:00] exited                                        ExecID= TaskID=0-0 exit_status=137 exited_at="2022-09-14 12:10:37.336458676 +0000 UTC" runtime=aws.firecracker vmID=0-0
ERRO[2022-09-14T05:10:37.343317886-07:00] error copying io                              ExecID= TaskID=0-0 error="reading from a closed fifo" runtime=aws.firecracker stream=stdin vmID=0-0
ERRO[2022-09-14T05:10:37.343335775-07:00] error closing io stream                       ExecID= TaskID=0-0 error="1 error occurred:\n\t* close unix @->firecracker.vsock: use of closed network connection\n\n" runtime=aws.firecracker stream=stdin vmID=0-0
DEBU[2022-09-14T05:10:37.343417811-07:00] event forwarded                               ns=firecracker-containerd topic=/tasks/exit type=containerd.events.TaskExit
DEBU[2022-09-14T05:10:37.860662305-07:00] event forwarded                               ns=firecracker-containerd topic=/tasks/delete type=containerd.events.TaskDelete
INFO[2022-09-14T05:10:37.899797044-07:00] PatchGuestDrive successful                    runtime=aws.firecracker
INFO[2022-09-14T05:10:37.900710421-07:00] shim disconnected                             id=0-0
WARN[2022-09-14T05:10:37.900816069-07:00] cleaning up after shim disconnected           id=0-0 namespace=firecracker-containerd
INFO[2022-09-14T05:10:37.900841296-07:00] cleaning up dead shim
ERRO[2022-09-14T05:10:42.343461702-07:00] error closing io stream                       ExecID= TaskID=0-0 error="1 error occurred:\n\t* close unix @->firecracker.vsock: use of closed network connection\n\n" runtime=aws.firecracker stream=stdout vmID=0-0
ERRO[2022-09-14T05:10:42.343559974-07:00] error closing io stream                       ExecID= TaskID=0-0 error="1 error occurred:\n\t* close unix @->firecracker.vsock: use of closed network connection\n\n" runtime=aws.firecracker stream=stderr vmID=0-0
ERRO[2022-09-14T05:10:42.957606414-07:00] failed to delete                              cmd="/usr/local/bin/containerd-shim-aws-firecracker -namespace firecracker-containerd -address /run/firecracker-containerd/containerd.sock -publish-binary /usr/local/bin/firecracker-containerd -id 0-0 -bundle /run/firecracker-containerd/io.containerd.runtime.v2.task/firecracker-containerd/0-0 delete" error="exit status 1"
WARN[2022-09-14T05:10:42.957822868-07:00] failed to clean up after shim disconnected    error="aws.firecracker: rpc error: code = DeadlineExceeded desc = timed out waiting for VM start\n: exit status 1" id=0-0 namespace=firecracker-containerd
DEBU[2022-09-14T05:10:42.960062011-07:00] remove snapshot                               key=0-0
DEBU[2022-09-14T05:10:42.971791617-07:00] event published                               ns=firecracker-containerd topic=/snapshot/remove type=containerd.events.SnapshotRemove
DEBU[2022-09-14T05:10:42.975091737-07:00] event published                               ns=firecracker-containerd topic=/containers/delete type=containerd.events.ContainerDelete
DEBU[2022-09-14T05:10:42.975657673-07:00] stop VM: VMID:"0-0"
INFO[2022-09-14T05:10:42.976271205-07:00] stopping the VM                               runtime=aws.firecracker vmID=0-0
ERRO[2022-09-14T05:10:42.978654846-07:00] error while forwarding events from VM agent   error="rpc error: code = Canceled desc = context canceled" runtime=aws.firecracker vmID=0-0
DEBU[2022-09-14T05:10:43.209008079-07:00] schedule snapshotter cleanup                  snapshotter=devmapper
DEBU[2022-09-14T05:10:43.209077522-07:00] walk
DEBU[2022-09-14T05:10:43.209220637-07:00] remove                                        key=firecracker-containerd/17/0-0
DEBU[2022-09-14T05:10:43.339336800-07:00] removed snapshot                              key=firecracker-containerd/17/0-0 snapshotter=devmapper
DEBU[2022-09-14T05:10:43.339400860-07:00] snapshot garbage collected                    d=130.338721ms snapshotter=devmapper
DEBU[2022-09-14T05:10:43.339416793-07:00] garbage collected                             d=2.914019ms
INFO[2022-09-14T05:10:43.371601457-07:00] firecracker exited: status=0                  runtime=aws.firecracker
DEBU[2022-09-14T05:10:43.372707050-07:00] event forwarded                               ns=firecracker-containerd topic=/firecracker-vm/stop type=VMStop
ERRO[2022-09-14T05:10:48.372939422-07:00] aws.firecracker: publisher not closed         shim_stream=stderr vmID=0-0
DEBU[2022-09-14T05:10:48.375125939-07:00] shim has been terminated                      error="exit status 1" vmID=0-0

I would appreciate any inputs towards solution. Thanks, Nirav.

niravnshah commented 1 year ago

Some additional information. May be helpful for this issue. I tried to run make test and after showing many tests to be passing, i get following output towards the end.

sudo mkdir -m777 -p /tmp/ctrd-logs && sudo env "PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/usr/local/go/bin:/home/nshah5/vhive/istio-1.12.5/bin:/usr/local/go/bin:/home/nshah5/vhive/istio-1.12.5/bin:/home/nshah5/vhive/istio-1.12.5/bin:/home/nshah5/vhive/istio-1.12.5/bin:/home/nshah5/vhive/istio-1.12.5/bin:/home/nshah5/vhive/istio-1.12.5/bin:/home/nshah5/vhive/istio-1.12.5/bin:/home/nshah5/vhive/istio-1.12.5/bin:/home/nshah5/vhive/istio-1.12.5/bin:/home/nshah5/vhive/istio-1.12.5/bin:/home/nshah5/vhive/istio-1.12.5/bin" /usr/local/bin/firecracker-containerd --config /etc/firecracker-containerd/config.toml 1>/tmp/ctrd-logs/fccd_orch_noupf_log_bench.out 2>/tmp/ctrd-logs/fccd_orch_noupf_log_bench.err &
sudo env "PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin:/usr/local/go/bin:/home/nshah5/vhive/istio-1.12.5/bin:/usr/local/go/bin:/home/nshah5/vhive/istio-1.12.5/bin:/home/nshah5/vhive/istio-1.12.5/bin:/home/nshah5/vhive/istio-1.12.5/bin:/home/nshah5/vhive/istio-1.12.5/bin:/home/nshah5/vhive/istio-1.12.5/bin:/home/nshah5/vhive/istio-1.12.5/bin:/home/nshah5/vhive/istio-1.12.5/bin:/home/nshah5/vhive/istio-1.12.5/bin:/home/nshah5/vhive/istio-1.12.5/bin:/home/nshah5/vhive/istio-1.12.5/bin" go test -short -v -race -cover -run TestProfileSingleConfiguration -args -test -loadStep 100 && sudo rm -rf bench_results
INFO[2022-09-14T06:32:43.139213242-07:00] Orchestrator snapshots enabled: false
INFO[2022-09-14T06:32:43.139334933-07:00] Orchestrator UPF enabled: false
INFO[2022-09-14T06:32:43.139352415-07:00] Orchestrator inMemWorkingSet enabled: false
INFO[2022-09-14T06:32:43.139369311-07:00] Orchestrator lazy serving mode enabled: false
INFO[2022-09-14T06:32:43.139385840-07:00] Orchestrator UPF metrics enabled: false
INFO[2022-09-14T06:32:43.139401530-07:00] Drop cache: true
INFO[2022-09-14T06:32:43.139416414-07:00] Bench dir: bench_results
INFO[2022-09-14T06:32:43.139435411-07:00] Registering bridges for tap manager
INFO[2022-09-14T06:32:43.140026361-07:00] Creating containerd client
INFO[2022-09-14T06:32:43.140990512-07:00] Created containerd client
INFO[2022-09-14T06:32:43.141110011-07:00] Creating firecracker client
INFO[2022-09-14T06:32:43.141563396-07:00] Created firecracker client
=== RUN   TestProfileSingleConfiguration
INFO[2022-09-14T06:32:43.174590566-07:00] New function added                            fID=0 image="ghcr.io/ease-lab/helloworld:var_workload" isPinned=true servedTh=0
WARN[2022-09-14T06:32:53.820615244-07:00] Failed to Fetch k8s dns clusterIP exit status 1
The connection to the server localhost:8080 was refused - did you specify the right host or port?

WARN[2022-09-14T06:32:53.820834234-07:00] Using google dns 8.8.8.8
INFO[2022-09-14T06:32:55.281169698-07:00] New function added                            fID=1 image="ghcr.io/ease-lab/helloworld:var_workload" isPinned=true servedTh=0
WARN[2022-09-14T06:32:55.303196825-07:00] Failed to Fetch k8s dns clusterIP exit status 1
The connection to the server localhost:8080 was refused - did you specify the right host or port?

WARN[2022-09-14T06:32:55.303279655-07:00] Using google dns 8.8.8.8
INFO[2022-09-14T06:32:56.800111163-07:00] Current RPS: 10
WARN[2022-09-14T06:32:56.800411068-07:00] Too many latency samples for 2 VM, measure 20 samples instead.
    perf_bench_test.go:389:
                Error Trace:    /home/nshah5/vhive/perf_bench_test.go:389
                                                        /home/nshah5/vhive/perf_bench_test.go:156
                Error:          Received unexpected error:
                                open profile.csv: no such file or directory
                Test:           TestProfileSingleConfiguration
                Messages:       Stopping profiler returned error: open profile.csv: no such file or directory
--- FAIL: TestProfileSingleConfiguration (34.67s)
FAIL
coverage: 34.1% of statements
INFO[2022-09-14T06:33:17.810474826-07:00] waiting for goroutines
INFO[2022-09-14T06:33:29.086403073-07:00] waiting done
INFO[2022-09-14T06:33:29.086621409-07:00] Closing fcClient
INFO[2022-09-14T06:33:29.086771383-07:00] Closing containerd client
INFO[2022-09-14T06:33:29.087000174-07:00] Removing bridges
exit status 1

This is also failing with similar error message that profile.csv is not found. apart from this, it is also showing this error.

WARN[2022-09-14T06:32:55.303196825-07:00] Failed to Fetch k8s dns clusterIP exit status 1
The connection to the server localhost:8080 was refused - did you specify the right host or port?

Do we need to be running a k8s cluster to be able to run profiling tool?

I tried to have a single node cluster running while trying to execute the profiling tool, however, in that case the profiling tool exited with this error

nshah5@d8eb97bf800a:~/vhive$ sudo env "PATH=$PATH" go test -v -timeout 99999s -run TestProfileIncrementConfiguration -args -funcNames helloworld -vmIncrStep 4 -maxVMNum 32 -nodes '!+Memory_Bound*/3,+MUX'
INFO[2022-09-14T05:02:17.733118141-07:00] Orchestrator snapshots enabled: false
INFO[2022-09-14T05:02:17.733147065-07:00] Orchestrator UPF enabled: false
INFO[2022-09-14T05:02:17.733150249-07:00] Orchestrator lazy serving mode enabled: false
INFO[2022-09-14T05:02:17.733154457-07:00] Orchestrator UPF metrics enabled: false
INFO[2022-09-14T05:02:17.733157474-07:00] Drop cache: true
INFO[2022-09-14T05:02:17.733159560-07:00] Bench dir: bench_results
INFO[2022-09-14T05:02:17.733162427-07:00] Registering bridges for tap manager
PANI[2022-09-14T05:02:17.733191966-07:00] Bridge could not be created                   bridge=br0
panic: (*logrus.Entry) 0xc0003b5500

goroutine 1 [running]:
github.com/sirupsen/logrus.(*Entry).log(0xc0003b5490, 0x0, {0xc0002fee00, 0x1b})
        /root/go/pkg/mod/github.com/sirupsen/logrus@v1.9.0/entry.go:260 +0x47e
github.com/sirupsen/logrus.(*Entry).Log(0xc0003b5490, 0x0, {0xc0002df998?, 0x604?, 0x0?})
        /root/go/pkg/mod/github.com/sirupsen/logrus@v1.9.0/entry.go:304 +0x4f
github.com/sirupsen/logrus.(*Entry).Panic(...)
        /root/go/pkg/mod/github.com/sirupsen/logrus@v1.9.0/entry.go:342
github.com/ease-lab/vhive/taps.createBridge({0xc00042c1c4, 0x3}, {0xc00042c1d0, 0xb})
        /home/nshah5/vhive/taps/tapManager.go:90 +0x297
github.com/ease-lab/vhive/taps.NewTapManager()
        /home/nshah5/vhive/taps/tapManager.go:72 +0x17d
github.com/ease-lab/vhive/misc.NewVMPool(...)
        /home/nshah5/vhive/misc/vm_pool.go:34
github.com/ease-lab/vhive/ctriface.NewOrchestrator({0x153c787, 0x9}, {0x0, 0x0}, {0xc0002dfe90, 0x5, 0x1?})
        /home/nshah5/vhive/ctriface/orch.go:99 +0x85
github.com/ease-lab/vhive.TestMain(0x84b311?)
        /home/nshah5/vhive/vhive_test.go:75 +0x465
main.main()
        _testmain.go:83 +0x1d3
exit status 2
FAIL    github.com/ease-lab/vhive       0.006s
niravnshah commented 1 year ago

Hi @ustiugov, I am trying to get the vHive profiling tool working to get the function cold start delay numbers. Any help in getting this profiling tool working would be highly appreciated. Is it possible to look into this issue? Or if you can provide some pointers also would be helpful.

Thanks, Nirav.

ustiugov commented 1 year ago

@niravnshah sorry for the late response. k8s setup is not required for the profiler to run.

Bridge could not be created bridge=br0 error indicates that you ran vHive repeatedly without cleaning the host setup after the previous run failed (and didn't delete the bridge because it died). You need to run the cleaning script as specified here.

Re: the missing file, please try to drill down the error. Currently, the profiler is not fully supported due to problems in its CI testing but we would love to bring it back. We would welcome contributions from the community.

ustiugov commented 1 year ago

@niravnshah please advise if you were able to solve the problem

niravnshah commented 1 year ago

Hi @ustiugov, not yet. I am still hitting the "Bridge could not be created" error. I feel it might be due to my system being behind a proxy, i tried to put multiple ip address in no_proxy but couldn't get it working.

ustiugov commented 1 year ago

no, I believe that this has nothing to do with the proxy. can you list all the bridges and see if there is already a bridge with the name br0?

niravnshah commented 1 year ago

ok got the issue. It was unsupported CPU for toplev as i am running on a test system image

Due to this profile.csv was not generated. Added "--force-cpu" option to get it working.

ustiugov commented 1 year ago

i see, thanks for sharing. Please close the issue if it's resolved

ustiugov commented 1 year ago

@niravnshah

niravnshah commented 1 year ago

@ustiugov, I am not getting the option to close the issue. Perhaps as i am not the one who opened it. image @dhuang-esl, can you please check if the solution mentioned by me above works for you as well? and if so, can you please close the issue?

ustiugov commented 1 year ago

ah , sorry. closing. @dhuang-esl please re-open if still relevant.