search

spotify / XCMetrics

XCMetrics is the easiest way to collect Xcode build metrics and improve developer productivity.
https://xcmetrics.io
Other
1.1k stars 77 forks source link

NIOPostgres error: protocol error: Bind count must be <= 32767 #30

Closed JustinDSN closed 3 years ago

JustinDSN commented 3 years ago

When attempting to upload an XCActivityLog that is rather large (29.1 MB) with many targets, and many steps, XCMetrics logs an error: [ ERROR ] Uncaught error: NIOPostgres error: protocol error: Bind count must be <= 32767.

A Google search for that error pointed me to: https://github.com/vapor/fluent-kit/issues/277. It seems to be related to the number of parameters that are being bound to a given query.

Here is what the breakpoint looks like after the log is parsed in the insert method of the PostgreSQLMetricsRepository struct.

Screen Shot 2021-02-17 at 11 43 05 PM

Here is the raw log output:


[ INFO ] PUT /v1/metrics [request-id: 8C8BB0F4-A820-4661-9CD9-30CEE2C6A0B0]
[ INFO ] Dispatched queue job [job_id: 9170D075-D21B-4204-9E87-7D693A934C7B, job_name: ProcessMetricsJob, queue: default, request-id: 8C8BB0F4-A820-4661-9CD9-30CEE2C6A0B0]
[ INFO ] PUT /v1/metrics [request-id: F0778FB1-7894-46C8-A053-6F236902A751]
[ INFO ] Dispatched queue job [job_id: 5995640B-3785-48A5-B4BD-08593C61822A, job_name: ProcessMetricsJob, queue: default, request-id: F0778FB1-7894-46C8-A053-6F236902A751]
[ INFO ] Dequeing job [job_id: 9170D075-D21B-4204-9E87-7D693A934C7B, job_name: ProcessMetricsJob, queue: default]
[ NOTICE ] 17/02/2021 23:24:35 [ProcessMetricsJob] message dequeued [job_id: 9170D075-D21B-4204-9E87-7D693A934C7B]
[ NOTICE ] 17/02/2021 23:24:35 [ProcessMetricsJob] fetching log from file:///var/folders/rm/0tz8w5hx4kb597326bxp7ksh0000gn/T/5A1D12F4-5F8F-4ECB-8225-E38746464152/2C2594C3-4B6C-4F07-9145-461019452E4C.xcactivitylog [job_id: 9170D075-D21B-4204-9E87-7D693A934C7B]
[ NOTICE ] 17/02/2021 23:24:35 [ProcessMetricsJob] log fetched to file:///var/folders/rm/0tz8w5hx4kb597326bxp7ksh0000gn/T/5A1D12F4-5F8F-4ECB-8225-E38746464152/2C2594C3-4B6C-4F07-9145-461019452E4C.xcactivitylog [job_id: 9170D075-D21B-4204-9E87-7D693A934C7B]
[ INFO ] Dequeing job [job_id: 5995640B-3785-48A5-B4BD-08593C61822A, job_name: ProcessMetricsJob, queue: default]
[ NOTICE ] 17/02/2021 23:24:35 [ProcessMetricsJob] message dequeued [job_id: 5995640B-3785-48A5-B4BD-08593C61822A]
[ NOTICE ] 17/02/2021 23:29:11 [ProcessMetricsJob] log parsed file:///var/folders/rm/0tz8w5hx4kb597326bxp7ksh0000gn/T/5A1D12F4-5F8F-4ECB-8225-E38746464152/2C2594C3-4B6C-4F07-9145-461019452E4C.xcactivitylog [job_id: 9170D075-D21B-4204-9E87-7D693A934C7B]
[ NOTICE ] 17/02/2021 23:29:11 [ProcessMetricsJob] fetching log from file:///var/folders/rm/0tz8w5hx4kb597326bxp7ksh0000gn/T/276EEDC9-A774-408C-B14E-9C04124D377C/5100D986-E078-4BD8-A894-9163DD594967.xcactivitylog [job_id: 5995640B-3785-48A5-B4BD-08593C61822A]
[ NOTICE ] 17/02/2021 23:29:11 [ProcessMetricsJob] log fetched to file:///var/folders/rm/0tz8w5hx4kb597326bxp7ksh0000gn/T/276EEDC9-A774-408C-B14E-9C04124D377C/5100D986-E078-4BD8-A894-9163DD594967.xcactivitylog [job_id: 5995640B-3785-48A5-B4BD-08593C61822A]
[ NOTICE ] 17/02/2021 23:29:11 [PostgressMetricsRepository] creating daily partitions
[ NOTICE ] 17/02/2021 23:29:11 [ProcessMetricsJob] log parsed file:///var/folders/rm/0tz8w5hx4kb597326bxp7ksh0000gn/T/276EEDC9-A774-408C-B14E-9C04124D377C/5100D986-E078-4BD8-A894-9163DD594967.xcactivitylog [job_id: 5995640B-3785-48A5-B4BD-08593C61822A]
[ NOTICE ] 17/02/2021 23:29:11 [PostgressMetricsRepository] creating daily partitions
[ NOTICE ] 17/02/2021 23:29:11 [PostgressMetricsRepository] creating daily partitions
[ NOTICE ] 17/02/2021 23:29:11 [PostgressMetricsRepository] creating daily partitions
[ ERROR ] Uncaught error: NIOPostgres error: protocol error: Bind count must be <= 32767.
[ NOTICE ] 17/02/2021 23:29:16 [PostgressMetricsRepository] metrics inserted
[ INFO ] [ProcessMetricsJob] metrics inserted for file:///var/folders/rm/0tz8w5hx4kb597326bxp7ksh0000gn/T/276EEDC9-A774-408C-B14E-9C04124D377C/5100D986-E078-4BD8-A894-9163DD594967.xcactivitylog [job_id: 5995640B-3785-48A5-B4BD-08593C61822A]
[ INFO ] [ProcessMetricsJob] finished processing file:///var/folders/rm/0tz8w5hx4kb597326bxp7ksh0000gn/T/276EEDC9-A774-408C-B14E-9C04124D377C/5100D986-E078-4BD8-A894-9163DD594967.xcactivitylog [job_id: 5995640B-3785-48A5-B4BD-08593C61822A]```
ecamacho commented 3 years ago

Yes, that a limitation in the NIO Postgres driver. We did some workarounds to be able to insert batches of some entities like notes and steps that we found in our tests that are easy to get over that limit. I think in your case, the issue is the number of targets. That is one list we did not apply our workaround and it may be causing it. Let me change that so you can test if it solves your issue.

ecamacho commented 3 years ago

Can you try with the latest main branch? We just merged a potential fix

JustinDSN commented 3 years ago

Thanks for the quick turnaround @ecamacho! I tried the latest ‘main’ branch with the same file, and while I got further (the same error didn’t happen), the file was never imported.

XcmetricsServer memory usage went up to about 5.5 gb, and the finished parsing log message was posted to the console, but no other successful messages were posted to the console.

I left the server running for several hours and no further messages about the status of the job were logged.

Any idea how to best trouble shoot this hanging behavior, or where to look next?

ecamacho commented 3 years ago

Hi @JustinDSN were you running the backend in MacOS or in Linux?

I think the issue is the amount of notes you have in your build (~376k). I will try to reproduce it locally.

I was checking and we run our Backend pods with 4G in RAM and 2 cores, meaning that we can parse 2 logs in parallel per pod.