The first launcher run never noticed the CL at all.

The second run first lists it at 16:38 (twenty minutes after it was marked ready).

16:38:19: INFO: Checking for change dgarrett:634133:035c94c1
16:38:19: INFO: Found manifest change dgarrett:634133:035c94c1

The CL then shows up as "in busy".

16:38:30: INFO: Changes in busy: CL:*427388 CL:*432592 CL:*435792 CL:*437087 CL:*437235 CL:*437613 CL:*438514 CL:*438732 CL:*438852 CL:*439012 CL:*439797 CL:*439853 CL:*439995 CL:*440034 CL:522345 CL:617511 CL:619750 CL:627035 CL:627261 CL:629160 CL:630356 CL:630381 CL:631038 CL:633708 CL:633845 CL:633853 CL:634127 CL:634133 CL:634184 CL:634212 CL:634266 CL:634272 CL:634323 CL:634332.
Changes in inflight: CL:*427388 CL:*432592 CL:*435792 CL:*437087 CL:*437235 CL:*437613 CL:*438514 CL:*438732 CL:*438852 CL:*439012 CL:*439797 CL:*439853 CL:*439995 CL:*440034 CL:522345 CL:617511 CL:619750 CL:627035 CL:627261 CL:629160 CL:630356 CL:630381 CL:631038 CL:633708 CL:633845 CL:633853 CL:634127 CL:634184 CL:634212 CL:634266 CL:634272 CL:634323 CL:634332.
Changes in verified: CL:*407788 CL:*427132 CL:*430613 CL:*430671 CL:*437193 CL:*437413 CL:*437612 CL:*437915 CL:*438312 CL:*438674 CL:*438992 CL:*439392 CL:*439772 CL:*439792 CL:*439799 CL:*439912 CL:413011 CL:451939 CL:452727 CL:503349 CL:503350 CL:510029 CL:535914 CL:556354 CL:559225 CL:568539 CL:578673 CL:580216 CL:580218 CL:580221 CL:580451 CL:580670 CL:583959 CL:584854 CL:584855 CL:593409 CL:596797 CL:597220 CL:599229 CL:602857 CL:605412 CL:611646 CL:611946 CL:612963 CL:616067 CL:617375 CL:618218 CL:618219 CL:619394 CL:620273 CL:620282 CL:620431 CL:621007 CL:621086 CL:624174 CL:624461 CL:624867 CL:624907 CL:627860 CL:628540 CL:629059 CL:629076 CL:629518 CL:629756 CL:629957 CL:629966 CL:629980 CL:630056 CL:630577 CL:630702 CL:630758 CL:631217 CL:631677 CL:631757 CL:632619 CL:633403 CL:633704 CL:633783 CL:633803 CL:633804 CL:633844 CL:633888 CL:633891 CL:634183 CL:634208 CL:634274.


And as "being verified"

16:39:19: INFO: CLs currently being verified: CL:634133

But it's not one of the jobs then launched:

16:39:19: INFO: Launching Pre-CQs for configs ['celes-no-vmtest-pre-cq', 'fizz-no-vmtest-pre-cq', 'reef-no-vmtest-pre-cq', 'chell-no-vmtest-pre-cq', 'gru-no-vmtest-pre-cq'] with changes CL:630056 CL:634274 CL:634275


The the same logging pattern seems to be repeating.

I don't see any log messages showing that the number of PreCQ jobs launched is limited:

http://cs/chromeos_public/chromite/cbuildbot/stages/sync_stages.py?l=1992&rcl=ddf9bcd2969fbcc61f671659e71700264618cf55

So... why weren't builds launched for this CL? If this is representative, this help explain poor PreCQ throughput.

FYI: For Chase-Pending, you'd have to convince us (just me? 'cause I've been living under a rock?) that there is a problem with "poor PreCQ throughput". Otherwise, the impact is not critical enough to justify Chase.

I've not been the one investigating, but I've been told that we are improving CQ performance, but making up for it by slowing PreCQ performance.

I suspect this is related.

Chase for just finding out (as the summary says) if the time spent waiting is too long for the pre-cq-launcher.

I looked into the clActionTable, the Pre-CQs were triggered 

mysql> select * from clActionTable where change_number = 634133  and patch_number = 1;


| 15804481 |  1785372 |        634133 |            1 | external      | trybot_launching          | daisy_spring-no-vmtest-pre-cq | 2017-08-24 23:24:05 | 8970336971696144304 |
| 15804482 |  1785372 |        634133 |            1 | external      | trybot_launching          | betty-pre-cq                  | 2017-08-24 23:24:05 | 8970336971295461856 |
| 15804483 |  1785372 |        634133 |            1 | external      | trybot_launching          | binhost-pre-cq                | 2017-08-24 23:24:05 | 8970336971020086224 |
| 15804484 |  1785372 |        634133 |            1 | external      | trybot_launching          | nyan_blaze-no-vmtest-pre-cq   | 2017-08-24 23:24:05 | 8970336970784100656 |
| 15804485 |  1785372 |        634133 |            1 | external      | trybot_launching          | reef-uni-no-vmtest-pre-cq     | 2017-08-24 23:24:05 | 8970336970554847728 |
| 15804486 |  1785372 |        634133 |            1 | external      | trybot_launching          | lumpy-no-vmtest-pre-cq        | 2017-08-24 23:24:05 | 8970336970379328928 |
| 15804487 |  1785372 |        634133 |            1 | external      | trybot_launching          | whirlwind-no-vmtest-pre-cq    | 2017-08-24 23:24:05 | 8970336970112734176 |
| 15804488 |  1785372 |        634133 |            1 | external      | trybot_launching          | kevin-no-vmtest-pre-cq        | 2017-08-24 23:24:05 | 8970336969820828560 |
| 15804489 |  1785372 |        634133 |            1 | external      | trybot_launching          | cyan-no-vmtest-pre-cq         | 2017-08-24 23:24:05 | 8970336969496282944 |
| 15804490 |  1785372 |        634133 |            1 | external      | trybot_launching          | samus-no-vmtest-pre-cq        | 2017-08-24 23:24:05 | 8970336969288561968 |
| 15804491 |  1785372 |        634133 |            1 | external      | trybot_launching          | reef-no-vmtest-pre-cq         | 2017-08-24 23:24:06 | 8970336968922342176 |



The reason Pre-CQ-launcher didn't mark it as pre-cq-verify is dgarrett@'s CL changed the behaviors of the Pre-CQ sync stage. Normal Pre-CQ (like https://uberchromegw.corp.google.com/i/chromiumos.tryserver/builders/no_vmtest_pre_cq/builds/122272) has the PreCQSync stage to mark its CL as picked up in CIDB, but the Pre-CQs in this example only have Sync stage. Pass this bug back to dgarrett@ to check why the stage behavior was changed.

Add the link of the triggered Pre-CQ example:

https://uberchromegw.corp.google.com/i/chromiumos.tryserver/builders/no_vmtest_pre_cq/builds/105412