Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[Bug]: Slow PVF execution in separate process #2123

Closed
kamilsa opened this issue Jun 13, 2024 · 4 comments · Fixed by #2199
Closed

[Bug]: Slow PVF execution in separate process #2123

kamilsa opened this issue Jun 13, 2024 · 4 comments · Fixed by #2199
Assignees
@Harrm @turuslan
Labels
bug Something isn't working Runtime

Comments

@kamilsa
Copy link
Contributor

kamilsa commented Jun 13, 2024

Bug Summary

Issue occurs when --parachain-single-process flag is not provided

Bug Description

It is observed that when --parachain-single-process flag is not provided PVF execution time is drastically slower.

Steps to Reproduce

During the execution of zombienet/polkadot/functional/0001-parachains-pvf.zndsl test with --parachain-single-process flag added there were the following execution times:

24.06.13 09:46:42.464610  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 337 ms
24.06.13 09:46:48.435971  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 273 ms
24.06.13 09:46:55.022460  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 294 ms
24.06.13 09:46:55.213458  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 484 ms
24.06.13 09:47:00.392891  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 247 ms
24.06.13 09:47:06.451197  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 307 ms
24.06.13 09:47:12.705043  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 191 ms
24.06.13 09:47:18.417648  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 245 ms
24.06.13 09:47:18.556004  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 136 ms
24.06.13 09:47:24.388348  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 240 ms
24.06.13 09:47:30.315966  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 170 ms
24.06.13 09:47:36.770884  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 163 ms
24.06.13 09:47:37.136053  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 518 ms
24.06.13 09:47:42.344387  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 213 ms
24.06.13 09:47:48.371995  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 272 ms
24.06.13 09:47:54.618380  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 476 ms
24.06.13 09:48:00.793122  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 543 ms
24.06.13 09:48:06.826347  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 536 ms
24.06.13 09:48:12.726246  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 600 ms
24.06.13 09:48:18.800589  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 483 ms
24.06.13 09:48:25.003346  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 219 ms
24.06.13 09:48:30.351778  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 154 ms
24.06.13 09:48:30.518747  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 320 ms
24.06.13 09:48:36.903490  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 711 ms
24.06.13 09:48:36.914686  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 722 ms
24.06.13 09:48:42.652574  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 524 ms
24.06.13 09:48:48.459002  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 244 ms
24.06.13 09:48:48.635134  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 418 ms
24.06.13 09:48:54.394874  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 275 ms
24.06.13 09:49:00.660355  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 558 ms
24.06.13 09:49:06.572422  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 439 ms
24.06.13 09:49:12.412997  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 189 ms
24.06.13 09:49:18.581708  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 154 ms
24.06.13 09:49:24.323560  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 154 ms
24.06.13 09:49:30.595910  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 474 ms
24.06.13 09:49:36.444391  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 227 ms
24.06.13 09:49:42.928065  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 323 ms
24.06.13 09:49:48.442094  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 212 ms
24.06.13 09:49:48.569911  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 339 ms
24.06.13 09:49:54.500129  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 359 ms

When flag was added execution times were:

24.06.13 09:38:18.232196  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 88 ms
24.06.13 09:38:24.200098  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 77 ms
24.06.13 09:38:30.220802  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 72 ms
24.06.13 09:38:36.369870  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 189 ms
24.06.13 09:38:42.479482  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 174 ms
24.06.13 09:38:48.217579  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 78 ms
24.06.13 09:38:54.638906  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 262 ms
24.06.13 09:38:54.712570  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 259 ms
24.06.13 09:38:54.785425  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 240 ms
24.06.13 09:39:00.226141  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 79 ms
24.06.13 09:39:06.467185  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 118 ms
24.06.13 09:39:06.539927  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 164 ms
24.06.13 09:39:12.342827  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 121 ms
24.06.13 09:39:18.243696  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 113 ms
24.06.13 09:39:24.117754  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 12 ms
24.06.13 09:39:24.132090  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 23 ms
24.06.13 09:39:30.197435  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 49 ms
24.06.13 09:39:36.134300  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 17 ms
24.06.13 09:39:42.243617  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 30 ms
24.06.13 09:39:42.256829  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 43 ms
24.06.13 09:39:42.280160  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 67 ms
24.06.13 09:39:48.557186  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 283 ms
24.06.13 09:39:48.567710  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 292 ms
24.06.13 09:39:48.577632  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 300 ms
24.06.13 09:39:54.082519  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 20 ms

Effects of the Bug

Slow PVF execution times

Expected Behavior

No response

System Information

Tested on Apple M1 Pro, 16GB RAM

Additional Context

No response
@kamilsa kamilsa added the bug Something isn't working label Jun 13, 2024
@kamilsa kamilsa assigned turuslan and unassigned Harrm Jun 13, 2024
@kamilsa kamilsa mentioned this issue Jun 13, 2024
Merged
@turuslan
Copy link
Contributor

turuslan commented Jun 24, 2024 •
edited
Loading

Apple M1, 16GB

type file size exec time
Debug 495MB 200ms
RelWithDebInfo 185MB 20ms

exec on debug is slow (maybe due to executable size or global initializers).
fork is fast (0.5ms).
node process may fork+exec initial worker process,
which will fork itself to "work" and stop these processes on timeout.

kagome
└ initial worker (slow start, starts and stops child workers)
  ├ worker 1 (fast start, does "work", stopped by parent on timeout)
  └ worker 2

@turuslan
Copy link
Contributor

turuslan commented Jun 24, 2024 •
edited
Loading

release polkadot-*-worker exe is 15MB (release wasmtime+cranelift is 5MB).
cpp wasmedge (with static llvm) is 120MB debug and 100MB release.

This was referenced Jun 28, 2024
Merged
Merged
@kamilsa
Copy link
Contributor Author

kamilsa commented Jul 19, 2024

Update with latest KAGOME version. Master c99ce28 (no --parachain-single-process )

24.07.19 16:42:31.311140  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 130 ms
24.07.19 16:42:36.276177  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 84 ms
24.07.19 16:42:42.324440  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 74 ms
24.07.19 16:42:49.470696  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 78 ms
24.07.19 16:42:55.990583  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 73 ms
24.07.19 16:43:00.765218  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 105 ms
24.07.19 16:43:01.153174  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 80 ms
24.07.19 16:43:07.115513  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 73 ms
24.07.19 16:43:13.715065  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 74 ms
24.07.19 16:43:19.486503  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 77 ms
24.07.19 16:43:24.525189  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 100 ms
24.07.19 16:43:31.235046  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 28 ms
24.07.19 16:43:36.174036  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 20 ms
24.07.19 16:43:43.668243  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 27 ms
24.07.19 16:43:49.464743  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 17 ms
24.07.19 16:43:54.310340  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 134 ms
24.07.19 16:44:01.391400  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 12 ms
24.07.19 16:44:06.297165  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 138 ms
24.07.19 16:44:07.113119  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 15 ms
24.07.19 16:44:12.213739  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 92 ms
24.07.19 16:44:19.442394  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 20 ms
24.07.19 16:44:25.337694  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 27 ms
24.07.19 16:44:25.696222  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 13 ms
24.07.19 16:44:30.264048  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 93 ms
24.07.19 16:44:36.281595  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 15 ms
24.07.19 16:44:36.294460  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 28 ms
24.07.19 16:44:37.277115  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 14 ms
24.07.19 16:44:42.279420  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 147 ms

Same commit with "--parachain-single-process":

24.07.19 17:06:42.252912  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 89 ms
24.07.19 17:06:48.431480  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 80 ms
24.07.19 17:06:48.501646  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 86 ms
24.07.19 17:06:49.116995  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 84 ms
24.07.19 17:06:55.540490  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 94 ms
24.07.19 17:07:07.587603  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 132 ms
24.07.19 17:07:12.354755  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 101 ms
24.07.19 17:07:18.289857  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 79 ms
24.07.19 17:07:25.496912  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 77 ms
24.07.19 17:07:37.665939  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 77 ms
24.07.19 17:07:42.184871  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 8 ms
24.07.19 17:07:48.093749  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 9 ms
24.07.19 17:07:55.066883  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 8 ms
24.07.19 17:08:01.737510  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 8 ms
24.07.19 17:08:07.217298  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 10 ms

On branch remove pvf reuse 931d044

24.07.19 17:20:01.574762  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 99 ms
24.07.19 17:20:06.267028  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 83 ms
24.07.19 17:20:13.648603  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 77 ms
24.07.19 17:20:18.538257  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 123 ms
24.07.19 17:20:19.265066  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 104 ms
24.07.19 17:20:25.389238  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 73 ms
24.07.19 17:20:30.428479  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 89 ms
24.07.19 17:20:30.514865  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 85 ms
24.07.19 17:20:36.424618  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 76 ms
24.07.19 17:20:37.674424  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 72 ms
24.07.19 17:20:42.322155  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 74 ms
24.07.19 17:20:49.490337  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 74 ms
24.07.19 17:20:55.268472  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 74 ms
24.07.19 17:21:00.256867  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 59 ms
24.07.19 17:21:07.094810  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 12 ms
24.07.19 17:21:12.289816  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 13 ms
24.07.19 17:21:13.184069  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 13 ms
24.07.19 17:21:19.304304  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 13 ms
24.07.19 17:21:24.162693  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 44 ms
24.07.19 17:21:30.172129  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 39 ms
24.07.19 17:21:37.474497  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 15 ms
24.07.19 17:21:43.079903  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 15 ms
24.07.19 17:21:48.287011  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 134 ms
24.07.19 17:21:49.120491  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 19 ms
24.07.19 17:21:54.197679  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 69 ms
24.07.19 17:22:00.192750  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 39 ms
24.07.19 17:22:06.117764  main_runner      Info      ParachainProcessorImpl  Parachain validation lasted for 17 ms

@kamilsa
Copy link
Contributor Author

kamilsa commented Jul 25, 2024

Closing it as now there is no much difference in executing pvf as a separate process or part of the main process

@kamilsa kamilsa closed this as completed Jul 25, 2024
@kamilsa kamilsa reopened this Aug 29, 2024
@turuslan turuslan mentioned this issue Aug 30, 2024
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@Harrm Harrm

@turuslan turuslan

Labels
bug Something isn't working Runtime
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

fix wasmedge spdlog qdrvm/kagome
3 participants
@kamilsa @Harrm @turuslan