Z3 timing variation

Since upgrading to the open source release of Z3 (latest git master), I've noticed a significant timing variation between repeated runs of nearly-identical SMT queries using the C API (anywhere from 2-122s). The only difference between the queries is the naming of arrays (in the QF_AUFBV logic).

We're allocating arrays as follows:

Z3_symbol s = Z3_mk_string_symbol(z3_context, arrayName);
Z3_mk_const(z3_context, s,
            Z3_mk_array_sort(z3_context, getSort(32), getSort(8)));

Below is an example query (converted to SMT-LIB). Replacing "arr51" with other names (e.g., "a" or "arr51_0x2628008") significantly changes the duration of the query, by up to two orders of magnitude. Repeated runs without varying the array name don't exhibit a significant timing variation.

Interestingly, the old binary release of Z3 3.2 doesn't seem to be affected by array naming (and runs faster for most of our queries).

(benchmark klee
:status unsat
:logic QF_AUFBV
:extrafuns ((arr51 Array[32:8]))
:assumption
(let (?x13 (concat (select arr51 bv58[32]) (concat (select arr51 bv57[32]) (select arr51 bv56[32]))))
(let (?x16 (concat (select arr51 bv59[32]) ?x13))
(let (?x23 (concat bv0[32] ?x16))
(let (?x34 (bvsub (bvadd (concat (extract[33:0] ?x23) bv0[30]) (concat (extract[35:0] ?x23) bv0[28])) (concat (extract[40:0] ?x23) bv0[23])))
(let (?x42 (bvadd (bvadd ?x34 (concat (extract[44:0] ?x23) bv0[19])) (concat (extract[45:0] ?x23) bv0[18])))
(let (?x50 (bvadd (bvsub ?x42 (concat (extract[47:0] ?x23) bv0[16])) (concat (extract[49:0] ?x23) bv0[14])))
(let (?x58 (bvsub (bvadd ?x50 (concat (extract[50:0] ?x23) bv0[13])) (concat (extract[52:0] ?x23) bv0[11])))
(let (?x66 (bvadd (bvadd ?x58 (concat (extract[56:0] ?x23) bv0[7])) (concat (extract[59:0] ?x23) bv0[4])))
(let (?x68 (extract[63:32] (bvsub ?x66 ?x23)))
(flet ($x79 (= bv1[32] bv30[32]))
(let (?x80 (ite $x79 (concat bv0[30] (extract[31:30] (bvsub ?x16 ?x68))) (ite (= bv1[32] bv31[32]) (concat bv0[31] (extract[31:31] (bvsub ?x16 ?x68))) bv0[32])))
(flet ($x85 (= bv1[32] bv29[32]))
(flet ($x90 (= bv1[32] bv28[32]))
(let (?x91 (ite $x90 (concat bv0[28] (extract[31:28] (bvsub ?x16 ?x68))) (ite $x85 (concat bv0[29] (extract[31:29] (bvsub ?x16 ?x68))) ?x80)))
(flet ($x96 (= bv1[32] bv27[32]))
(flet ($x102 (= bv1[32] bv26[32]))
(let (?x103 (ite $x102 (concat bv0[26] (extract[31:26] (bvsub ?x16 ?x68))) (ite $x96 (concat bv0[27] (extract[31:27] (bvsub ?x16 ?x68))) ?x91)))
(flet ($x108 (= bv1[32] bv25[32]))
(flet ($x114 (= bv1[32] bv24[32]))
(let (?x115 (ite $x114 (concat bv0[24] (extract[31:24] (bvsub ?x16 ?x68))) (ite $x108 (concat bv0[25] (extract[31:25] (bvsub ?x16 ?x68))) ?x103)))
(flet ($x119 (= bv1[32] bv23[32]))
(flet ($x125 (= bv1[32] bv22[32]))
(let (?x126 (ite $x125 (concat bv0[22] (extract[31:22] (bvsub ?x16 ?x68))) (ite $x119 (concat bv0[23] (extract[31:23] (bvsub ?x16 ?x68))) ?x115)))
(flet ($x131 (= bv1[32] bv21[32]))
(flet ($x137 (= bv1[32] bv20[32]))
(let (?x138 (ite $x137 (concat bv0[20] (extract[31:20] (bvsub ?x16 ?x68))) (ite $x131 (concat bv0[21] (extract[31:21] (bvsub ?x16 ?x68))) ?x126)))
(flet ($x142 (= bv1[32] bv19[32]))
(flet ($x147 (= bv1[32] bv18[32]))
(let (?x148 (ite $x147 (concat bv0[18] (extract[31:18] (bvsub ?x16 ?x68))) (ite $x142 (concat bv0[19] (extract[31:19] (bvsub ?x16 ?x68))) ?x138)))
(flet ($x153 (= bv1[32] bv17[32]))
(flet ($x157 (= bv1[32] bv16[32]))
(let (?x158 (ite $x157 (concat bv0[16] (extract[31:16] (bvsub ?x16 ?x68))) (ite $x153 (concat bv0[17] (extract[31:17] (bvsub ?x16 ?x68))) ?x148)))
(flet ($x163 (= bv1[32] bv15[32]))
(flet ($x168 (= bv1[32] bv14[32]))
(let (?x169 (ite $x168 (concat bv0[14] (extract[31:14] (bvsub ?x16 ?x68))) (ite $x163 (concat bv0[15] (extract[31:15] (bvsub ?x16 ?x68))) ?x158)))
(flet ($x173 (= bv1[32] bv13[32]))
(flet ($x179 (= bv1[32] bv12[32]))
(let (?x180 (ite $x179 (concat bv0[12] (extract[31:12] (bvsub ?x16 ?x68))) (ite $x173 (concat bv0[13] (extract[31:13] (bvsub ?x16 ?x68))) ?x169)))
(flet ($x184 (= bv1[32] bv11[32]))
(flet ($x190 (= bv1[32] bv10[32]))
(let (?x191 (ite $x190 (concat bv0[10] (extract[31:10] (bvsub ?x16 ?x68))) (ite $x184 (concat bv0[11] (extract[31:11] (bvsub ?x16 ?x68))) ?x180)))
(flet ($x196 (= bv1[32] bv9[32]))
(flet ($x202 (= bv1[32] bv8[32]))
(let (?x203 (ite $x202 (concat bv0[8] (extract[31:8] (bvsub ?x16 ?x68))) (ite $x196 (concat bv0[9] (extract[31:9] (bvsub ?x16 ?x68))) ?x191)))
(flet ($x207 (= bv1[32] bv7[32]))
(flet ($x213 (= bv1[32] bv6[32]))
(let (?x214 (ite $x213 (concat bv0[6] (extract[31:6] (bvsub ?x16 ?x68))) (ite $x207 (concat bv0[7] (extract[31:7] (bvsub ?x16 ?x68))) ?x203)))
(flet ($x219 (= bv1[32] bv5[32]))
(flet ($x224 (= bv1[32] bv4[32]))
(let (?x225 (ite $x224 (concat bv0[4] (extract[31:4] (bvsub ?x16 ?x68))) (ite $x219 (concat bv0[5] (extract[31:5] (bvsub ?x16 ?x68))) ?x214)))
(flet ($x230 (= bv1[32] bv3[32]))
(flet ($x236 (= bv1[32] bv2[32]))
(let (?x237 (ite $x236 (concat bv0[2] (extract[31:2] (bvsub ?x16 ?x68))) (ite $x230 (concat bv0[3] (extract[31:3] (bvsub ?x16 ?x68))) ?x225)))
(flet ($x241 (= bv1[32] bv1[32]))
(let (?x69 (bvsub ?x16 ?x68))
(flet ($x243 (= bv1[32] bv0[32]))
(let (?x245 (bvadd (ite $x243 ?x69 (ite $x241 (concat bv0[1] (extract[31:1] ?x69)) ?x237)) ?x68))
(let (?x253 (ite (= bv16[32] bv30[32]) (concat bv0[30] (extract[31:30] ?x245)) (ite (= bv16[32] bv31[32]) (concat bv0[31] (extract[31:31] ?x245)) bv0[32])))
(let (?x261 (ite (= bv16[32] bv28[32]) (concat bv0[28] (extract[31:28] ?x245)) (ite (= bv16[32] bv29[32]) (concat bv0[29] (extract[31:29] ?x245)) ?x253)))
(let (?x269 (ite (= bv16[32] bv26[32]) (concat bv0[26] (extract[31:26] ?x245)) (ite (= bv16[32] bv27[32]) (concat bv0[27] (extract[31:27] ?x245)) ?x261)))
(let (?x277 (ite (= bv16[32] bv24[32]) (concat bv0[24] (extract[31:24] ?x245)) (ite (= bv16[32] bv25[32]) (concat bv0[25] (extract[31:25] ?x245)) ?x269)))
(let (?x285 (ite (= bv16[32] bv22[32]) (concat bv0[22] (extract[31:22] ?x245)) (ite (= bv16[32] bv23[32]) (concat bv0[23] (extract[31:23] ?x245)) ?x277)))
(let (?x293 (ite (= bv16[32] bv20[32]) (concat bv0[20] (extract[31:20] ?x245)) (ite (= bv16[32] bv21[32]) (concat bv0[21] (extract[31:21] ?x245)) ?x285)))
(let (?x301 (ite (= bv16[32] bv18[32]) (concat bv0[18] (extract[31:18] ?x245)) (ite (= bv16[32] bv19[32]) (concat bv0[19] (extract[31:19] ?x245)) ?x293)))
(let (?x309 (ite (= bv16[32] bv16[32]) (concat bv0[16] (extract[31:16] ?x245)) (ite (= bv16[32] bv17[32]) (concat bv0[17] (extract[31:17] ?x245)) ?x301)))
(let (?x317 (ite (= bv16[32] bv14[32]) (concat bv0[14] (extract[31:14] ?x245)) (ite (= bv16[32] bv15[32]) (concat bv0[15] (extract[31:15] ?x245)) ?x309)))
(let (?x325 (ite (= bv16[32] bv12[32]) (concat bv0[12] (extract[31:12] ?x245)) (ite (= bv16[32] bv13[32]) (concat bv0[13] (extract[31:13] ?x245)) ?x317)))
(let (?x333 (ite (= bv16[32] bv10[32]) (concat bv0[10] (extract[31:10] ?x245)) (ite (= bv16[32] bv11[32]) (concat bv0[11] (extract[31:11] ?x245)) ?x325)))
(let (?x341 (ite (= bv16[32] bv8[32]) (concat bv0[8] (extract[31:8] ?x245)) (ite (= bv16[32] bv9[32]) (concat bv0[9] (extract[31:9] ?x245)) ?x333)))
(let (?x349 (ite (= bv16[32] bv6[32]) (concat bv0[6] (extract[31:6] ?x245)) (ite (= bv16[32] bv7[32]) (concat bv0[7] (extract[31:7] ?x245)) ?x341)))
(let (?x357 (ite (= bv16[32] bv4[32]) (concat bv0[4] (extract[31:4] ?x245)) (ite (= bv16[32] bv5[32]) (concat bv0[5] (extract[31:5] ?x245)) ?x349)))
(let (?x365 (ite (= bv16[32] bv2[32]) (concat bv0[2] (extract[31:2] ?x245)) (ite (= bv16[32] bv3[32]) (concat bv0[3] (extract[31:3] ?x245)) ?x357)))
(let (?x371 (ite (= bv16[32] bv0[32]) ?x245 (ite (= bv16[32] bv1[32]) (concat bv0[1] (extract[31:1] ?x245)) ?x365)))
(let (?x372 (concat bv0[32] ?x371))
(let (?x380 (bvsub (bvadd (concat (extract[32:0] ?x372) bv0[31]) (concat (extract[34:0] ?x372) bv0[29])) (concat (extract[36:0] ?x372) bv0[27])))
(let (?x386 (bvsub (bvadd ?x380 (concat (extract[38:0] ?x372) bv0[25])) (concat (extract[40:0] ?x372) bv0[23])))
(let (?x392 (bvsub (bvadd ?x386 (concat (extract[42:0] ?x372) bv0[21])) (concat (extract[44:0] ?x372) bv0[19])))
(let (?x398 (bvsub (bvadd ?x392 (concat (extract[46:0] ?x372) bv0[17])) (concat (extract[48:0] ?x372) bv0[15])))
(let (?x404 (bvsub (bvadd ?x398 (concat (extract[50:0] ?x372) bv0[13])) (concat (extract[52:0] ?x372) bv0[11])))
(let (?x410 (bvsub (bvadd ?x404 (concat (extract[54:0] ?x372) bv0[9])) (concat (extract[56:0] ?x372) bv0[7])))
(let (?x416 (bvsub (bvadd ?x410 (concat (extract[58:0] ?x372) bv0[5])) (concat (extract[60:0] ?x372) bv0[3])))
(let (?x420 (extract[63:32] (bvadd ?x416 (concat (extract[62:0] ?x372) bv0[1]))))
(let (?x427 (ite $x79 (concat bv0[30] (extract[31:30] (bvsub ?x371 ?x420))) (ite (= bv1[32] bv31[32]) (concat bv0[31] (extract[31:31] (bvsub ?x371 ?x420))) bv0[32])))
(let (?x433 (ite $x90 (concat bv0[28] (extract[31:28] (bvsub ?x371 ?x420))) (ite $x85 (concat bv0[29] (extract[31:29] (bvsub ?x371 ?x420))) ?x427)))
(let (?x439 (ite $x102 (concat bv0[26] (extract[31:26] (bvsub ?x371 ?x420))) (ite $x96 (concat bv0[27] (extract[31:27] (bvsub ?x371 ?x420))) ?x433)))
(let (?x445 (ite $x114 (concat bv0[24] (extract[31:24] (bvsub ?x371 ?x420))) (ite $x108 (concat bv0[25] (extract[31:25] (bvsub ?x371 ?x420))) ?x439)))
(let (?x451 (ite $x125 (concat bv0[22] (extract[31:22] (bvsub ?x371 ?x420))) (ite $x119 (concat bv0[23] (extract[31:23] (bvsub ?x371 ?x420))) ?x445)))
(let (?x457 (ite $x137 (concat bv0[20] (extract[31:20] (bvsub ?x371 ?x420))) (ite $x131 (concat bv0[21] (extract[31:21] (bvsub ?x371 ?x420))) ?x451)))
(let (?x463 (ite $x147 (concat bv0[18] (extract[31:18] (bvsub ?x371 ?x420))) (ite $x142 (concat bv0[19] (extract[31:19] (bvsub ?x371 ?x420))) ?x457)))
(let (?x469 (ite $x157 (concat bv0[16] (extract[31:16] (bvsub ?x371 ?x420))) (ite $x153 (concat bv0[17] (extract[31:17] (bvsub ?x371 ?x420))) ?x463)))
(let (?x475 (ite $x168 (concat bv0[14] (extract[31:14] (bvsub ?x371 ?x420))) (ite $x163 (concat bv0[15] (extract[31:15] (bvsub ?x371 ?x420))) ?x469)))
(let (?x481 (ite $x179 (concat bv0[12] (extract[31:12] (bvsub ?x371 ?x420))) (ite $x173 (concat bv0[13] (extract[31:13] (bvsub ?x371 ?x420))) ?x475)))
(let (?x487 (ite $x190 (concat bv0[10] (extract[31:10] (bvsub ?x371 ?x420))) (ite $x184 (concat bv0[11] (extract[31:11] (bvsub ?x371 ?x420))) ?x481)))
(let (?x493 (ite $x202 (concat bv0[8] (extract[31:8] (bvsub ?x371 ?x420))) (ite $x196 (concat bv0[9] (extract[31:9] (bvsub ?x371 ?x420))) ?x487)))
(let (?x499 (ite $x213 (concat bv0[6] (extract[31:6] (bvsub ?x371 ?x420))) (ite $x207 (concat bv0[7] (extract[31:7] (bvsub ?x371 ?x420))) ?x493)))
(let (?x505 (ite $x224 (concat bv0[4] (extract[31:4] (bvsub ?x371 ?x420))) (ite $x219 (concat bv0[5] (extract[31:5] (bvsub ?x371 ?x420))) ?x499)))
(let (?x511 (ite $x236 (concat bv0[2] (extract[31:2] (bvsub ?x371 ?x420))) (ite $x230 (concat bv0[3] (extract[31:3] (bvsub ?x371 ?x420))) ?x505)))
(let (?x421 (bvsub ?x371 ?x420))
(let (?x516 (bvadd (ite $x243 ?x421 (ite $x241 (concat bv0[1] (extract[31:1] ?x421)) ?x511)) ?x420))
(let (?x524 (ite (= bv3[32] bv30[32]) (concat bv0[30] (extract[31:30] ?x516)) (ite (= bv3[32] bv31[32]) (concat bv0[31] (extract[31:31] ?x516)) bv0[32])))
(let (?x532 (ite (= bv3[32] bv28[32]) (concat bv0[28] (extract[31:28] ?x516)) (ite (= bv3[32] bv29[32]) (concat bv0[29] (extract[31:29] ?x516)) ?x524)))
(let (?x540 (ite (= bv3[32] bv26[32]) (concat bv0[26] (extract[31:26] ?x516)) (ite (= bv3[32] bv27[32]) (concat bv0[27] (extract[31:27] ?x516)) ?x532)))
(let (?x548 (ite (= bv3[32] bv24[32]) (concat bv0[24] (extract[31:24] ?x516)) (ite (= bv3[32] bv25[32]) (concat bv0[25] (extract[31:25] ?x516)) ?x540)))
(let (?x556 (ite (= bv3[32] bv22[32]) (concat bv0[22] (extract[31:22] ?x516)) (ite (= bv3[32] bv23[32]) (concat bv0[23] (extract[31:23] ?x516)) ?x548)))
(let (?x564 (ite (= bv3[32] bv20[32]) (concat bv0[20] (extract[31:20] ?x516)) (ite (= bv3[32] bv21[32]) (concat bv0[21] (extract[31:21] ?x516)) ?x556)))
(let (?x572 (ite (= bv3[32] bv18[32]) (concat bv0[18] (extract[31:18] ?x516)) (ite (= bv3[32] bv19[32]) (concat bv0[19] (extract[31:19] ?x516)) ?x564)))
(let (?x580 (ite (= bv3[32] bv16[32]) (concat bv0[16] (extract[31:16] ?x516)) (ite (= bv3[32] bv17[32]) (concat bv0[17] (extract[31:17] ?x516)) ?x572)))
(let (?x588 (ite (= bv3[32] bv14[32]) (concat bv0[14] (extract[31:14] ?x516)) (ite (= bv3[32] bv15[32]) (concat bv0[15] (extract[31:15] ?x516)) ?x580)))
(let (?x596 (ite (= bv3[32] bv12[32]) (concat bv0[12] (extract[31:12] ?x516)) (ite (= bv3[32] bv13[32]) (concat bv0[13] (extract[31:13] ?x516)) ?x588)))
(let (?x604 (ite (= bv3[32] bv10[32]) (concat bv0[10] (extract[31:10] ?x516)) (ite (= bv3[32] bv11[32]) (concat bv0[11] (extract[31:11] ?x516)) ?x596)))
(let (?x612 (ite (= bv3[32] bv8[32]) (concat bv0[8] (extract[31:8] ?x516)) (ite (= bv3[32] bv9[32]) (concat bv0[9] (extract[31:9] ?x516)) ?x604)))
(let (?x620 (ite (= bv3[32] bv6[32]) (concat bv0[6] (extract[31:6] ?x516)) (ite (= bv3[32] bv7[32]) (concat bv0[7] (extract[31:7] ?x516)) ?x612)))
(let (?x628 (ite (= bv3[32] bv4[32]) (concat bv0[4] (extract[31:4] ?x516)) (ite (= bv3[32] bv5[32]) (concat bv0[5] (extract[31:5] ?x516)) ?x620)))
(let (?x636 (ite (= bv3[32] bv2[32]) (concat bv0[2] (extract[31:2] ?x516)) (ite (= bv3[32] bv3[32]) (concat bv0[3] (extract[31:3] ?x516)) ?x628)))
(let (?x642 (ite (= bv3[32] bv0[32]) ?x516 (ite (= bv3[32] bv1[32]) (concat bv0[1] (extract[31:1] ?x516)) ?x636)))
(let (?x648 (bvsub ?x371 (bvadd (concat (extract[28:0] ?x642) bv0[3]) (concat (extract[30:0] ?x642) bv0[1]))))
(= bv253[8] (extract[7:0] ?x648))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))))
:assumption
(let (?x13 (concat (select arr51 bv58[32]) (concat (select arr51 bv57[32]) (select arr51 bv56[32]))))
(let (?x16 (concat (select arr51 bv59[32]) ?x13))
(not (= bv4294967295[32] ?x16))))
:assumption
(let (?x13 (concat (select arr51 bv58[32]) (concat (select arr51 bv57[32]) (select arr51 bv56[32]))))
(let (?x16 (concat (select arr51 bv59[32]) ?x13))
(bvule bv100000[32] ?x16)))
:assumption
(let (?x13 (concat (select arr51 bv58[32]) (concat (select arr51 bv57[32]) (select arr51 bv56[32]))))
(let (?x16 (concat (select arr51 bv59[32]) ?x13))
(bvule ?x16 bv999999[32])))
:assumption
(let (?x13 (concat (select arr51 bv58[32]) (concat (select arr51 bv57[32]) (select arr51 bv56[32]))))
(let (?x16 (concat (select arr51 bv59[32]) ?x13))
(let (?x17 (sign_extend[32] ?x16))
(bvsle bv0[64] ?x17))))
:formula
true
)

I've tried explicitly setting the random seeds, but this (unsurprisingly) hasn't helped:

Z3_set_param_value(z3_config, "ARITH_RANDOM_SEED", "0");
Z3_set_param_value(z3_config, "RANDOM_SEED", "0");

Is it normal for Z3 to display such significant timing variation just by changing the names of symbols?

Also, is there any array naming scheme that would reduce solver time across the board?

Thanks!

We observe this kind of discrepancy in benchmarks that contain expressions of the form

(bvadd t_1 ... t_n), or
(bvmul t_1 ... t_n)

The benchmark may not explicitly contain this kind of term. For example, the term (bvadd a (bvsub b (bvadd c d)) is simplified to a nary sum.

In many instances, the order of the terms t_is have a dramatic effect on performance. The variable names affect the order of these terms. Z3 has two formula simplifiers.

The old one (located at src/ast/simplifier) uses the internal ids associated with each expression to sort arguments of AC operators. This approach is not affected by name changes, but it has another nasty side-effect: the order we create expressions affect the internal id assignment, and consequently the order of the terms t_i. This was an issue in many Z3 applications.

The new simplifier (located at src/ast/rewriter) uses a different approach. It sorts expressions using a total order based on the structure of expressions. In this new approach, the order we create expressions does not matter, but the names do. New code uses this new formula simplifier. However, we still have old code that uses the old simplifier.

For QF_AUFBV benchmarks, both formula simplifiers are used. This will change in the future, after we replace all occurrences of the old simplifier with the new one.

Finally, it would be great if you could send us the set of benchmarks where you are having performance problems. It would help us to improve Z3.

EDIT

I'd like to emphasize that the main issue is the occurrence of expressions of the form (bvadd t_1 ... t_n). Second, for QF_AUFBV benchmarks both simplifiers are used. In the current version, it is hard to avoid this timing fluctuations. For example, we should also observe timing fluctuations if we reorder the assumptions.

Here is a description of what happens in your instance, and why the name affects the behavior. It is a little bit technical, but it should clarify what is going on.

1- The new simplifier is executed. This simplifier caches intermediate results using a hashtable. The hashcode of an AST depends on the names used for constants and function symbols.

2- After the new simplifier is done, the cache is deleted. We traverse the ASTs stored in the cache and decrement their reference counters. If the counter is zero, the AST is deleted. IMPORTANT: the order of the ASTs in the hashtable depends on their hash code. So, the hash code (and consequently the names) may affect the order ASTs are deleted.

3- The AST manager in Z3 assigns an internal ID to each AST node. When an AST node is deleted, its ID is recycled. That is, the ID can be assigned to new AST nodes. We do that because we don't want to run out of IDs.

4- When the old simplifier is executed, it will create new ASTs, and recycled IDs are assigned to these new ASTs.

5- Since, the old simplifier uses IDs to sort the arguments of bvadd, we can get a different order when we change the name of a variable.

Summary

Different name ==> Different Hash ==> Different order in the Hashtable ==> Different deletion order ==> Recycled IDs are reused in different order ==> new ASTs with different IDs ==> Affects how the old simplifier orders the arguments of bvadd