two functions in query doubles time?? - Mailing list pgsql-general

PostGreSQL 8.0Beta1 (yes I know there is a new version, I will upgrade soon)
The 3 Explain Analyze results are at the bottom of the message. I tries
attaching them as text files but it wouldn't take them.

I have a view that selects 2 functions, plus other data from a view and 2
tables.
A Select * on the join take approximately 1.3 seconds.
Select function a() from the join takes about 1.3 seconds.
select function b() from the join takes about 1.3 seconds.
select a(),b() from the join takes about 2.5 seconds.
I am looking at the Explain Analyze for the previous 3 queries and it looks
like a number of the joins are taking 50% longer in the last query.
Does this make sense? Is there a reason for this?

As an immediate example below are the third line of the Explain Analyze from
each file:
Function A
"  ->  Hash Join  (cost=1104.25..1144.80 rows=9 width=20) (actual
time=102.214..105.482 rows=86 loops=1)"
Function B
"  ->  Hash Join  (cost=1104.25..1144.80 rows=9 width=45) (actual
time=102.882..106.548 rows=86 loops=1)"
Function A and B
"  ->  Hash Join  (cost=1104.25..1144.80 rows=9 width=49) (actual
time=147.010..152.254 rows=86 loops=1)"

As you can see the cost on the 3 lines is exactly the same and the actual
time from the functions alone are very similar.
The actual time from the query that selected the results of both functions
is a little less then 50% higher.
The rest of the files are similar to this example.

Thank You
Sim


Explain with just Function A
"Hash Join  (cost=1105.36..1146.07 rows=9 width=12) (actual
time=115.845..1275.877 rows=86 loops=1)"
"  Hash Cond: ("outer".ownerid = "inner".ownerid)"
"  ->  Hash Join  (cost=1104.25..1144.80 rows=9 width=20) (actual
time=102.214..105.482 rows=86 loops=1)"
"        Hash Cond: ("outer".partid = "inner".partid)"
"        ->  Seq Scan on parts b  (cost=0.00..33.97 rows=1297 width=4)
(actual time=0.009..1.561 rows=1297 loops=1)"
"        ->  Hash  (cost=1104.23..1104.23 rows=9 width=24) (actual
time=102.186..102.186 rows=0 loops=1)"
"              ->  Merge Left Join  (cost=1092.54..1104.23 rows=9 width=24)
(actual time=97.036..102.094 rows=86 loops=1)"
"                    Merge Cond: ("outer".partid = "inner".partid)"
"                    ->  Merge Left Join  (cost=859.02..870.67 rows=9
width=24) (actual time=89.722..94.573 rows=86 loops=1)"
"                          Merge Cond: (("outer".partid = "inner".partid)
AND ("outer".ownerid = "inner".ownerid))"
"                          ->  Merge Left Join  (cost=511.49..523.00 rows=9
width=24) (actual time=30.576..33.639 rows=86 loops=1)"
"                                Merge Cond: (("outer".partid =
"inner".partid) AND ("outer".ownerid = "inner".ownerid))"
"                                Filter:
((COALESCE(COALESCE("inner".realstock, 0::bigint), 0::bigint) -
COALESCE("outer".reserved, 0::bigint)) < 0)"
"                                ->  Sort  (cost=374.29..374.31 rows=9
width=24) (actual time=21.936..22.130 rows=309 loops=1)"
"                                      Sort Key: parts.partid,
owners.ownerid"
"                                      ->  Hash Join  (cost=333.24..374.15
rows=9 width=24) (actual time=17.805..21.532 rows=309 loops=1)"
"                                            Hash Cond: ("outer".ownerid =
"inner".ownerid)"
"                                            ->  Hash Join
(cost=332.13..372.82 rows=24 width=20) (actual time=17.763..20.728 rows=309
loops=1)"
"                                                  Hash Cond:
("outer".partid = "inner".partid)"
"                                                  ->  Seq Scan on parts
(cost=0.00..33.97 rows=1297 width=4) (actual time=0.006..1.378 rows=1297
loops=1)"
"                                                  ->  Hash
(cost=332.07..332.07 rows=24 width=16) (actual time=17.742..17.742 rows=0
loops=1)"
"                                                        ->  Subquery Scan b
(cost=331.41..332.07 rows=24 width=16) (actual time=16.437..17.455 rows=309
loops=1)"
"                                                              ->
HashAggregate  (cost=331.41..331.83 rows=24 width=12) (actual
time=16.432..16.907 rows=309 loops=1)"
"                                                                    Filter:
((sum((- quantity)) IS NOT NULL) AND (sum((- quantity)) > 0))"
"                                                                    ->
Hash Join  (cost=320.63..331.11 rows=24 width=12) (actual
time=14.662..15.552 rows=565 loops=1)"
"
Hash Cond: ("outer".batchid = "inner".refid)"
"                                                                          -
>  Seq Scan on batches a  (cost=0.00..7.90 rows=156 width=8) (actual
time=0.187..0.237 rows=19 loops=1)"
"
Filter: (batchactive = true)"
"                                                                          -
>  Hash  (cost=320.51..320.51 rows=48 width=12) (actual time=14.459..14.459
rows=0 loops=1)"
"
     ->  Index Scan using targetidsl on stocklog b  (cost=0.00..320.51
rows=48 width=12) (actual time=0.228..13.741 rows=787 loops=1)"
"
Index Cond: (transtypeid = 3)"
"
Filter: (commited = false)"
"                                            ->  Hash  (cost=1.09..1.09
rows=9 width=4) (actual time=0.025..0.025 rows=0 loops=1)"
"                                                  ->  Seq Scan on owners
(cost=0.00..1.09 rows=9 width=4) (actual time=0.003..0.015 rows=9 loops=1)"
"                                ->  Sort  (cost=137.20..141.01 rows=1523
width=16) (actual time=8.588..9.263 rows=1076 loops=1)"
"                                      Sort Key: c.partid, c.ownerid"
"                                      ->  Subquery Scan c
(cost=37.65..56.69 rows=1523 width=16) (actual time=3.636..7.083 rows=1084
loops=1)"
"                                            ->  HashAggregate
(cost=37.65..41.46 rows=1523 width=12) (actual time=3.632..5.166 rows=1084
loops=1)"
"                                                  ->  Seq Scan on stock
(cost=0.00..26.23 rows=1523 width=12) (actual time=0.004..1.578 rows=1523
loops=1)"
"                          ->  Sort  (cost=347.53..347.56 rows=12 width=8)
(actual time=59.118..59.683 rows=898 loops=1)"
"                                Sort Key: d.partid, d.ownerid"
"                                ->  Subquery Scan d  (cost=347.01..347.31
rows=12 width=8) (actual time=54.422..57.795 rows=908 loops=1)"
"                                      ->  HashAggregate
(cost=347.01..347.19 rows=12 width=33) (actual time=54.416..56.160 rows=908
loops=1)"
"                                            ->  Hash Join
(cost=69.08..346.86 rows=12 width=33) (actual time=17.597..44.846 rows=3496
loops=1)"
"                                                  Hash Cond: ("outer".poid
= "inner".poid)"
"                                                  ->  Seq Scan on poparts b
(cost=0.00..255.53 rows=4415 width=29) (actual time=0.022..14.701 rows=8712
loops=1)"
"                                                        Filter:
(((requestedby IS NULL) AND (promisedby IS NULL) AND (deliverywks = -1) AND
(purchaseagreemet = true)) = false)"
"                                                  ->  Hash
(cost=69.06..69.06 rows=9 width=12) (actual time=8.621..8.621 rows=0
loops=1)"
"                                                        ->  Index Scan
using postatusidpo on pos a  (cost=0.00..69.06 rows=9 width=12) (actual
time=0.040..7.048 rows=1717 loops=1)"
"                                                              Index Cond:
((postatusid >= 20) AND (postatusid <= 80))"
"                                                              Filter:
(isrfq = false)"
"                    ->  Sort  (cost=233.52..233.52 rows=1 width=4) (actual
time=7.301..7.309 rows=8 loops=1)"
"                          Sort Key: b.partid"
"                          ->  Subquery Scan b  (cost=233.46..233.51 rows=1
width=4) (actual time=7.209..7.278 rows=8 loops=1)"
"                                ->  GroupAggregate  (cost=233.46..233.50
rows=1 width=25) (actual time=7.204..7.257 rows=8 loops=1)"
"                                      Filter: (sum((quantity -
COALESCE(deliveredsum, 0))) > 0)"
"                                      ->  Sort  (cost=233.46..233.46 rows=1
width=25) (actual time=7.173..7.181 rows=12 loops=1)"
"                                            Sort Key: poparts.partid,
poparts.purchaseagreemet, poparts.requestedby, poparts.promisedby,
poparts.deliverywks, poparts.quantity, poparts.deliveredsum"
"                                            ->  Seq Scan on poparts
(cost=0.00..233.45 rows=1 width=25) (actual time=3.758..7.132 rows=12
loops=1)"
"                                                  Filter:
((purchaseagreemet = true) AND (requestedby IS NULL) AND (promisedby IS
NULL) AND (deliverywks = -1))"
"  ->  Hash  (cost=1.09..1.09 rows=9 width=4) (actual time=0.039..0.039
rows=0 loops=1)"
"        ->  Seq Scan on owners c  (cost=0.00..1.09 rows=9 width=4) (actual
time=0.014..0.028 rows=9 loops=1)"
"Total runtime: 1277.016 ms"


Explain with just Function B
"Hash Join  (cost=1105.36..1146.11 rows=9 width=41) (actual
time=106.047..1117.853 rows=86 loops=1)"
"  Hash Cond: ("outer".ownerid = "inner".ownerid)"
"  ->  Hash Join  (cost=1104.25..1144.80 rows=9 width=45) (actual
time=102.882..106.548 rows=86 loops=1)"
"        Hash Cond: ("outer".partid = "inner".partid)"
"        ->  Seq Scan on parts b  (cost=0.00..33.97 rows=1297 width=4)
(actual time=0.010..1.687 rows=1297 loops=1)"
"        ->  Hash  (cost=1104.23..1104.23 rows=9 width=49) (actual
time=102.853..102.853 rows=0 loops=1)"
"              ->  Merge Left Join  (cost=1092.54..1104.23 rows=9 width=49)
(actual time=97.566..102.750 rows=86 loops=1)"
"                    Merge Cond: ("outer".partid = "inner".partid)"
"                    ->  Merge Left Join  (cost=859.02..870.67 rows=9
width=41) (actual time=89.913..94.828 rows=86 loops=1)"
"                          Merge Cond: (("outer".partid = "inner".partid)
AND ("outer".ownerid = "inner".ownerid))"
"                          ->  Merge Left Join  (cost=511.49..523.00 rows=9
width=32) (actual time=30.603..33.613 rows=86 loops=1)"
"                                Merge Cond: (("outer".partid =
"inner".partid) AND ("outer".ownerid = "inner".ownerid))"
"                                Filter:
((COALESCE(COALESCE("inner".realstock, 0::bigint), 0::bigint) -
COALESCE("outer".reserved, 0::bigint)) < 0)"
"                                ->  Sort  (cost=374.29..374.31 rows=9
width=24) (actual time=21.928..22.108 rows=309 loops=1)"
"                                      Sort Key: parts.partid,
owners.ownerid"
"                                      ->  Hash Join  (cost=333.24..374.15
rows=9 width=24) (actual time=17.807..21.538 rows=309 loops=1)"
"                                            Hash Cond: ("outer".ownerid =
"inner".ownerid)"
"                                            ->  Hash Join
(cost=332.13..372.82 rows=24 width=20) (actual time=17.764..20.682 rows=309
loops=1)"
"                                                  Hash Cond:
("outer".partid = "inner".partid)"
"                                                  ->  Seq Scan on parts
(cost=0.00..33.97 rows=1297 width=4) (actual time=0.006..1.385 rows=1297
loops=1)"
"                                                  ->  Hash
(cost=332.07..332.07 rows=24 width=16) (actual time=17.743..17.743 rows=0
loops=1)"
"                                                        ->  Subquery Scan b
(cost=331.41..332.07 rows=24 width=16) (actual time=16.447..17.457 rows=309
loops=1)"
"                                                              ->
HashAggregate  (cost=331.41..331.83 rows=24 width=12) (actual
time=16.442..16.918 rows=309 loops=1)"
"                                                                    Filter:
((sum((- quantity)) IS NOT NULL) AND (sum((- quantity)) > 0))"
"                                                                    ->
Hash Join  (cost=320.63..331.11 rows=24 width=12) (actual
time=14.661..15.578 rows=565 loops=1)"
"
Hash Cond: ("outer".batchid = "inner".refid)"
"                                                                          -
>  Seq Scan on batches a  (cost=0.00..7.90 rows=156 width=8) (actual
time=0.231..0.285 rows=19 loops=1)"
"
Filter: (batchactive = true)"
"                                                                          -
>  Hash  (cost=320.51..320.51 rows=48 width=12) (actual time=14.413..14.413
rows=0 loops=1)"
"
     ->  Index Scan using targetidsl on stocklog b  (cost=0.00..320.51
rows=48 width=12) (actual time=0.226..13.677 rows=787 loops=1)"
"
Index Cond: (transtypeid = 3)"
"
Filter: (commited = false)"
"                                            ->  Hash  (cost=1.09..1.09
rows=9 width=4) (actual time=0.026..0.026 rows=0 loops=1)"
"                                                  ->  Seq Scan on owners
(cost=0.00..1.09 rows=9 width=4) (actual time=0.005..0.016 rows=9 loops=1)"
"                                ->  Sort  (cost=137.20..141.01 rows=1523
width=16) (actual time=8.625..9.294 rows=1076 loops=1)"
"                                      Sort Key: c.partid, c.ownerid"
"                                      ->  Subquery Scan c
(cost=37.65..56.69 rows=1523 width=16) (actual time=3.655..7.091 rows=1084
loops=1)"
"                                            ->  HashAggregate
(cost=37.65..41.46 rows=1523 width=12) (actual time=3.650..5.218 rows=1084
loops=1)"
"                                                  ->  Seq Scan on stock
(cost=0.00..26.23 rows=1523 width=12) (actual time=0.005..1.581 rows=1523
loops=1)"
"                          ->  Sort  (cost=347.53..347.56 rows=12 width=17)
(actual time=59.281..59.830 rows=898 loops=1)"
"                                Sort Key: d.partid, d.ownerid"
"                                ->  Subquery Scan d  (cost=347.01..347.31
rows=12 width=17) (actual time=54.327..57.955 rows=908 loops=1)"
"                                      ->  HashAggregate
(cost=347.01..347.19 rows=12 width=33) (actual time=54.321..56.123 rows=908
loops=1)"
"                                            ->  Hash Join
(cost=69.08..346.86 rows=12 width=33) (actual time=18.009..45.129 rows=3496
loops=1)"
"                                                  Hash Cond: ("outer".poid
= "inner".poid)"
"                                                  ->  Seq Scan on poparts b
(cost=0.00..255.53 rows=4415 width=29) (actual time=0.023..15.032 rows=8712
loops=1)"
"                                                        Filter:
(((requestedby IS NULL) AND (promisedby IS NULL) AND (deliverywks = -1) AND
(purchaseagreemet = true)) = false)"
"                                                  ->  Hash
(cost=69.06..69.06 rows=9 width=12) (actual time=8.949..8.949 rows=0
loops=1)"
"                                                        ->  Index Scan
using postatusidpo on pos a  (cost=0.00..69.06 rows=9 width=12) (actual
time=0.079..7.197 rows=1717 loops=1)"
"                                                              Index Cond:
((postatusid >= 20) AND (postatusid <= 80))"
"                                                              Filter:
(isrfq = false)"
"                    ->  Sort  (cost=233.52..233.52 rows=1 width=12) (actual
time=7.635..7.639 rows=8 loops=1)"
"                          Sort Key: b.partid"
"                          ->  Subquery Scan b  (cost=233.46..233.51 rows=1
width=12) (actual time=7.523..7.608 rows=8 loops=1)"
"                                ->  GroupAggregate  (cost=233.46..233.50
rows=1 width=25) (actual time=7.518..7.587 rows=8 loops=1)"
"                                      Filter: (sum((quantity -
COALESCE(deliveredsum, 0))) > 0)"
"                                      ->  Sort  (cost=233.46..233.46 rows=1
width=25) (actual time=7.485..7.512 rows=12 loops=1)"
"                                            Sort Key: poparts.partid,
poparts.purchaseagreemet, poparts.requestedby, poparts.promisedby,
poparts.deliverywks, poparts.quantity, poparts.deliveredsum"
"                                            ->  Seq Scan on poparts
(cost=0.00..233.45 rows=1 width=25) (actual time=3.928..7.443 rows=12
loops=1)"
"                                                  Filter:
((purchaseagreemet = true) AND (requestedby IS NULL) AND (promisedby IS
NULL) AND (deliverywks = -1))"
"  ->  Hash  (cost=1.09..1.09 rows=9 width=4) (actual time=0.086..0.086
rows=0 loops=1)"
"        ->  Seq Scan on owners c  (cost=0.00..1.09 rows=9 width=4) (actual
time=0.062..0.074 rows=9 loops=1)"
"Total runtime: 1119.082 ms"

Explain with Function A and B
"Hash Join  (cost=1105.36..1146.13 rows=9 width=45) (actual
time=163.641..2898.518 rows=86 loops=1)"
"  Hash Cond: ("outer".ownerid = "inner".ownerid)"
"  ->  Hash Join  (cost=1104.25..1144.80 rows=9 width=49) (actual
time=147.010..152.254 rows=86 loops=1)"
"        Hash Cond: ("outer".partid = "inner".partid)"
"        ->  Seq Scan on parts b  (cost=0.00..33.97 rows=1297 width=4)
(actual time=0.011..1.789 rows=1297 loops=1)"
"        ->  Hash  (cost=1104.23..1104.23 rows=9 width=49) (actual
time=146.979..146.979 rows=0 loops=1)"
"              ->  Merge Left Join  (cost=1092.54..1104.23 rows=9 width=49)
(actual time=141.739..146.878 rows=86 loops=1)"
"                    Merge Cond: ("outer".partid = "inner".partid)"
"                    ->  Merge Left Join  (cost=859.02..870.67 rows=9
width=41) (actual time=134.175..139.036 rows=86 loops=1)"
"                          Merge Cond: (("outer".partid = "inner".partid)
AND ("outer".ownerid = "inner".ownerid))"
"                          ->  Merge Left Join  (cost=511.49..523.00 rows=9
width=32) (actual time=30.955..33.953 rows=86 loops=1)"
"                                Merge Cond: (("outer".partid =
"inner".partid) AND ("outer".ownerid = "inner".ownerid))"
"                                Filter:
((COALESCE(COALESCE("inner".realstock, 0::bigint), 0::bigint) -
COALESCE("outer".reserved, 0::bigint)) < 0)"
"                                ->  Sort  (cost=374.29..374.31 rows=9
width=24) (actual time=21.908..22.106 rows=309 loops=1)"
"                                      Sort Key: parts.partid,
owners.ownerid"
"                                      ->  Hash Join  (cost=333.24..374.15
rows=9 width=24) (actual time=17.710..21.507 rows=309 loops=1)"
"                                            Hash Cond: ("outer".ownerid =
"inner".ownerid)"
"                                            ->  Hash Join
(cost=332.13..372.82 rows=24 width=20) (actual time=17.667..20.689 rows=309
loops=1)"
"                                                  Hash Cond:
("outer".partid = "inner".partid)"
"                                                  ->  Seq Scan on parts
(cost=0.00..33.97 rows=1297 width=4) (actual time=0.025..1.475 rows=1297
loops=1)"
"                                                  ->  Hash
(cost=332.07..332.07 rows=24 width=16) (actual time=17.624..17.624 rows=0
loops=1)"
"                                                        ->  Subquery Scan b
(cost=331.41..332.07 rows=24 width=16) (actual time=16.330..17.317 rows=309
loops=1)"
"                                                              ->
HashAggregate  (cost=331.41..331.83 rows=24 width=12) (actual
time=16.325..16.793 rows=309 loops=1)"
"                                                                    Filter:
((sum((- quantity)) IS NOT NULL) AND (sum((- quantity)) > 0))"
"                                                                    ->
Hash Join  (cost=320.63..331.11 rows=24 width=12) (actual
time=14.607..15.479 rows=565 loops=1)"
"
Hash Cond: ("outer".batchid = "inner".refid)"
"                                                                          -
>  Seq Scan on batches a  (cost=0.00..7.90 rows=156 width=8) (actual
time=0.241..0.298 rows=19 loops=1)"
"
Filter: (batchactive = true)"
"                                                                          -
>  Hash  (cost=320.51..320.51 rows=48 width=12) (actual time=14.349..14.349
rows=0 loops=1)"
"
     ->  Index Scan using targetidsl on stocklog b  (cost=0.00..320.51
rows=48 width=12) (actual time=0.230..13.613 rows=787 loops=1)"
"
Index Cond: (transtypeid = 3)"
"
Filter: (commited = false)"
"                                            ->  Hash  (cost=1.09..1.09
rows=9 width=4) (actual time=0.025..0.025 rows=0 loops=1)"
"                                                  ->  Seq Scan on owners
(cost=0.00..1.09 rows=9 width=4) (actual time=0.004..0.016 rows=9 loops=1)"
"                                ->  Sort  (cost=137.20..141.01 rows=1523
width=16) (actual time=8.993..9.655 rows=1076 loops=1)"
"                                      Sort Key: c.partid, c.ownerid"
"                                      ->  Subquery Scan c
(cost=37.65..56.69 rows=1523 width=16) (actual time=3.920..7.419 rows=1084
loops=1)"
"                                            ->  HashAggregate
(cost=37.65..41.46 rows=1523 width=12) (actual time=3.914..5.587 rows=1084
loops=1)"
"                                                  ->  Seq Scan on stock
(cost=0.00..26.23 rows=1523 width=12) (actual time=0.005..1.670 rows=1523
loops=1)"
"                          ->  Sort  (cost=347.53..347.56 rows=12 width=17)
(actual time=103.187..103.743 rows=898 loops=1)"
"                                Sort Key: d.partid, d.ownerid"
"                                ->  Subquery Scan d  (cost=347.01..347.31
rows=12 width=17) (actual time=97.246..101.774 rows=908 loops=1)"
"                                      ->  HashAggregate
(cost=347.01..347.19 rows=12 width=33) (actual time=97.240..99.150 rows=908
loops=1)"
"                                            ->  Hash Join
(cost=69.08..346.86 rows=12 width=33) (actual time=19.115..74.672 rows=3496
loops=1)"
"                                                  Hash Cond: ("outer".poid
= "inner".poid)"
"                                                  ->  Seq Scan on poparts b
(cost=0.00..255.53 rows=4415 width=29) (actual time=0.053..21.468 rows=8712
loops=1)"
"                                                        Filter:
(((requestedby IS NULL) AND (promisedby IS NULL) AND (deliverywks = -1) AND
(purchaseagreemet = true)) = false)"
"                                                  ->  Hash
(cost=69.06..69.06 rows=9 width=12) (actual time=9.641..9.641 rows=0
loops=1)"
"                                                        ->  Index Scan
using postatusidpo on pos a  (cost=0.00..69.06 rows=9 width=12) (actual
time=0.107..7.927 rows=1717 loops=1)"
"                                                              Index Cond:
((postatusid >= 20) AND (postatusid <= 80))"
"                                                              Filter:
(isrfq = false)"
"                    ->  Sort  (cost=233.52..233.52 rows=1 width=12) (actual
time=7.548..7.552 rows=8 loops=1)"
"                          Sort Key: b.partid"
"                          ->  Subquery Scan b  (cost=233.46..233.51 rows=1
width=12) (actual time=7.450..7.520 rows=8 loops=1)"
"                                ->  GroupAggregate  (cost=233.46..233.50
rows=1 width=25) (actual time=7.445..7.501 rows=8 loops=1)"
"                                      Filter: (sum((quantity -
COALESCE(deliveredsum, 0))) > 0)"
"                                      ->  Sort  (cost=233.46..233.46 rows=1
width=25) (actual time=7.414..7.422 rows=12 loops=1)"
"                                            Sort Key: poparts.partid,
poparts.purchaseagreemet, poparts.requestedby, poparts.promisedby,
poparts.deliverywks, poparts.quantity, poparts.deliveredsum"
"                                            ->  Seq Scan on poparts
(cost=0.00..233.45 rows=1 width=25) (actual time=3.837..7.367 rows=12
loops=1)"
"                                                  Filter:
((purchaseagreemet = true) AND (requestedby IS NULL) AND (promisedby IS
NULL) AND (deliverywks = -1))"
"  ->  Hash  (cost=1.09..1.09 rows=9 width=4) (actual time=0.039..0.039
rows=0 loops=1)"
"        ->  Seq Scan on owners c  (cost=0.00..1.09 rows=9 width=4) (actual
time=0.015..0.029 rows=9 loops=1)"
"Total runtime: 2899.822 ms"