Formulas in workflows & validation - lazy or eager evaluated?

Question

I tried to run some tests in developer edition and didn't see great difference so I am not sure.

Basically I have a case that CPU time is leaking somewhere and I suspect it's validation rules or workflows. There is skip_flag setting on each of them, which in the case of lazy evaluation wouldn't be the most efficient design as all criterion would evaluate first (i.e. record type name checks).

In case of eager evaluation that wouldn't mater. So far I found that Apex is lazy evaluated. Salesforce docs themselves say that poorly designed formulas do contribute to CPU time.

Sample workflow rule:

false == true && RecordType.Name == 'Test2'

vs

RecordType.Name == 'Test2' && false == true

(In real world scenario false == true would be something like $permission.skip_workflow).

Simple test code via execute anonymous:

system.debug('init ' + limits.getCpuTime());
account[] testAcc = new account[]{};

    for (integer i=0; i<1000; i++){
        testAcc.add (new account (name = 'bunny'+i, recordtypeid= '01228000000YSb5AAG'));
    }
insert testAcc;

system.debug('fin ' + limits.getCpuTime());

Trigger on account:

trigger acc on Account (after insert) {
    system.debug('init ' + limits.getCpuTime());
    if(trigger.isInsert && trigger.isAfter){    
        integer startTime = limits.getCpuTime();
        account[] accList = new account[]{};
            for (account a: trigger.new) {

                if (a.name.startsWith('bunny')){
                    accList.add ( new account (id = a.id, name = '1' + a.name));
                }
            }
        update accList;
        integer endTime = limits.getCpuTime();
        system.debug('time spent ' + (endTime - startTime));
    }
    system.debug('fin ' + limits.getCpuTime());
}

Result of 'correct' run:

    19:29:29.236 (1236253657)|USER_DEBUG|[2]|DEBUG|init 218
    19:29:30.433 (2433681531)|USER_DEBUG|[14]|DEBUG|time spent 182
    19:29:30.433 (2433779634)|USER_DEBUG|[16]|DEBUG|fin 400
    19:29:31.383 (3383811210)|USER_DEBUG|[2]|DEBUG|init 547
    19:29:32.318 (4318653559)|USER_DEBUG|[14]|DEBUG|time spent 186
    19:29:32.318 (4318728992)|USER_DEBUG|[16]|DEBUG|fin 733
    19:29:33.384 (5384519465)|USER_DEBUG|[2]|DEBUG|init 879
    19:29:34.463 (6463341239)|USER_DEBUG|[14]|DEBUG|time spent 194
    19:29:34.463 (6463415658)|USER_DEBUG|[16]|DEBUG|fin 1073
    19:29:35.519 (7519942400)|USER_DEBUG|[2]|DEBUG|init 1221
    19:29:36.496 (8496883237)|USER_DEBUG|[14]|DEBUG|time spent 176
    19:29:36.496 (8496963064)|USER_DEBUG|[16]|DEBUG|fin 1397
    19:29:37.359 (9359159436)|USER_DEBUG|[2]|DEBUG|init 1539
    19:29:38.342 (10342250700)|USER_DEBUG|[14]|DEBUG|time spent 175
    19:29:38.342 (10342325892)|USER_DEBUG|[16]|DEBUG|fin 1714
    19:29:38.418 (10418464850)|USER_DEBUG|[10]|DEBUG|fin 1758


Result of `RecordType.Name == 'Test2' && false == true`:

    19:36:08.049 (1049372513)|USER_DEBUG|[2]|DEBUG|init 272
    19:36:08.983 (1983787717)|USER_DEBUG|[14]|DEBUG|time spent 220
    19:36:08.983 (1983884750)|USER_DEBUG|[16]|DEBUG|fin 493
    19:36:09.894 (2894742216)|USER_DEBUG|[2]|DEBUG|init 675
    19:36:10.938 (3938129600)|USER_DEBUG|[14]|DEBUG|time spent 221
    19:36:10.938 (3938195554)|USER_DEBUG|[16]|DEBUG|fin 896
    19:36:11.806 (4806611755)|USER_DEBUG|[2]|DEBUG|init 1076
    19:36:12.848 (5848225244)|USER_DEBUG|[14]|DEBUG|time spent 219
    19:36:12.848 (5848291219)|USER_DEBUG|[16]|DEBUG|fin 1295
    19:36:13.718 (6718297370)|USER_DEBUG|[2]|DEBUG|init 1480
    19:36:14.755 (7755367410)|USER_DEBUG|[14]|DEBUG|time spent 221
    19:36:14.755 (7755433819)|USER_DEBUG|[16]|DEBUG|fin 1701
    19:36:15.737 (8737164443)|USER_DEBUG|[2]|DEBUG|init 1883
    19:36:16.791 (9791173333)|USER_DEBUG|[14]|DEBUG|time spent 217
    19:36:16.791 (9791239558)|USER_DEBUG|[16]|DEBUG|fin 2100
    19:36:16.882 (9882798832)|USER_DEBUG|[10]|DEBUG|fin 2159

Update

So I've added validation rules to the game as well. Total 4 workflows & 5 validation rules. Results doesn't answer anything:

bad workflow & bad validation
19:45:22.029 (29863337)|USER_DEBUG|[1]|DEBUG|init 1
19:45:23.196 (1196572307)|USER_DEBUG|[2]|DEBUG|acc init 318
19:45:24.361 (2361776520)|USER_DEBUG|[14]|DEBUG|time spent 282
19:45:24.361 (2361895795)|USER_DEBUG|[16]|DEBUG|acc fin 600
19:45:25.319 (3319016988)|USER_DEBUG|[2]|DEBUG|acc init 849
19:45:26.976 (4976219560)|USER_DEBUG|[14]|DEBUG|time spent 277
19:45:26.976 (4976305829)|USER_DEBUG|[16]|DEBUG|acc fin 1126
19:45:27.877 (5877641858)|USER_DEBUG|[2]|DEBUG|acc init 1373
19:45:29.084 (7084450462)|USER_DEBUG|[14]|DEBUG|time spent 276
19:45:29.084 (7084536240)|USER_DEBUG|[16]|DEBUG|acc fin 1649
19:45:29.968 (7968697713)|USER_DEBUG|[2]|DEBUG|acc init 1890
19:45:31.101 (9101794407)|USER_DEBUG|[14]|DEBUG|time spent 277
19:45:31.101 (9101877707)|USER_DEBUG|[16]|DEBUG|acc fin 2168
19:45:32.101 (10101652278)|USER_DEBUG|[2]|DEBUG|acc init 2406
19:45:33.318 (11318407651)|USER_DEBUG|[14]|DEBUG|time spent 272
19:45:33.318 (11318496313)|USER_DEBUG|[16]|DEBUG|acc fin 2678
19:45:33.382 (11382123108)|USER_DEBUG|[9]|DEBUG|fin 2732

Run 2
19:47:48.033 (33814622)|USER_DEBUG|[2]|DEBUG|init 0
19:47:49.121 (1121384677)|USER_DEBUG|[2]|DEBUG|acc init 274
19:47:50.294 (2294961600)|USER_DEBUG|[14]|DEBUG|time spent 249
19:47:50.295 (2295048078)|USER_DEBUG|[16]|DEBUG|acc fin 523
19:47:51.215 (3215977141)|USER_DEBUG|[2]|DEBUG|acc init 748
19:47:52.550 (4550959161)|USER_DEBUG|[14]|DEBUG|time spent 250
19:47:52.551 (4551021960)|USER_DEBUG|[16]|DEBUG|acc fin 998
19:47:53.478 (5478457911)|USER_DEBUG|[2]|DEBUG|acc init 1210
19:47:54.528 (6528890097)|USER_DEBUG|[14]|DEBUG|time spent 236
19:47:54.528 (6528953174)|USER_DEBUG|[16]|DEBUG|acc fin 1446
19:47:55.423 (7423184852)|USER_DEBUG|[2]|DEBUG|acc init 1656
19:47:56.532 (8532641567)|USER_DEBUG|[14]|DEBUG|time spent 241
19:47:56.532 (8532715169)|USER_DEBUG|[16]|DEBUG|acc fin 1897
19:47:57.429 (9429871926)|USER_DEBUG|[2]|DEBUG|acc init 2110
19:47:58.533 (10533773667)|USER_DEBUG|[14]|DEBUG|time spent 239
19:47:58.533 (10533838059)|USER_DEBUG|[16]|DEBUG|acc fin 2349
19:47:58.590 (10590414521)|USER_DEBUG|[10]|DEBUG|fin 2394

Run 3
19:48:51.029 (29047949)|USER_DEBUG|[2]|DEBUG|init 1
19:48:52.097 (1097472930)|USER_DEBUG|[2]|DEBUG|acc init 279
19:48:53.151 (2151734413)|USER_DEBUG|[14]|DEBUG|time spent 261
19:48:53.151 (2151817804)|USER_DEBUG|[16]|DEBUG|acc fin 540
19:48:54.078 (3078499551)|USER_DEBUG|[2]|DEBUG|acc init 762
19:48:55.113 (4113754734)|USER_DEBUG|[14]|DEBUG|time spent 256
19:48:55.113 (4113817461)|USER_DEBUG|[16]|DEBUG|acc fin 1018
19:48:56.035 (5035450756)|USER_DEBUG|[2]|DEBUG|acc init 1237
19:48:57.033 (6033627532)|USER_DEBUG|[14]|DEBUG|time spent 256
19:48:57.033 (6033692923)|USER_DEBUG|[16]|DEBUG|acc fin 1493
19:48:57.984 (6984115348)|USER_DEBUG|[2]|DEBUG|acc init 1714
19:48:59.084 (8084668616)|USER_DEBUG|[14]|DEBUG|time spent 259
19:48:59.084 (8084732725)|USER_DEBUG|[16]|DEBUG|acc fin 1973
19:49:00.012 (9012916353)|USER_DEBUG|[2]|DEBUG|acc init 2193
19:49:01.136 (10136165895)|USER_DEBUG|[14]|DEBUG|time spent 264
19:49:01.136 (10136229018)|USER_DEBUG|[16]|DEBUG|acc fin 2457
19:49:01.194 (10194794393)|USER_DEBUG|[10]|DEBUG|fin 2507



good workflow & validation
19:51:46.036 (36680191)|USER_DEBUG|[1]|DEBUG|init 0
19:51:47.099 (1099440477)|USER_DEBUG|[2]|DEBUG|acc init 262
19:51:48.124 (2124357352)|USER_DEBUG|[14]|DEBUG|time spent 240
19:51:48.124 (2124446678)|USER_DEBUG|[16]|DEBUG|acc fin 502
19:51:49.074 (3074403236)|USER_DEBUG|[2]|DEBUG|acc init 697
19:51:50.096 (4096581374)|USER_DEBUG|[14]|DEBUG|time spent 228
19:51:50.096 (4096648592)|USER_DEBUG|[16]|DEBUG|acc fin 925
19:51:50.884 (4884798020)|USER_DEBUG|[2]|DEBUG|acc init 1105
19:51:51.957 (5957841752)|USER_DEBUG|[14]|DEBUG|time spent 234
19:51:51.957 (5957909808)|USER_DEBUG|[16]|DEBUG|acc fin 1339
19:51:52.852 (6852905904)|USER_DEBUG|[2]|DEBUG|acc init 1528
19:51:53.963 (7963063907)|USER_DEBUG|[14]|DEBUG|time spent 227
19:51:53.963 (7963132706)|USER_DEBUG|[16]|DEBUG|acc fin 1755
19:51:54.902 (8902252135)|USER_DEBUG|[2]|DEBUG|acc init 1931
19:51:55.886 (9886728114)|USER_DEBUG|[14]|DEBUG|time spent 217
19:51:55.886 (9886811260)|USER_DEBUG|[16]|DEBUG|acc fin 2148
19:51:55.934 (9934797488)|USER_DEBUG|[9]|DEBUG|fin 2186

Run 2
19:52:41.026 (26435435)|USER_DEBUG|[1]|DEBUG|init 0
19:52:42.076 (1076968771)|USER_DEBUG|[2]|DEBUG|acc init 318
19:52:43.179 (2179639052)|USER_DEBUG|[14]|DEBUG|time spent 278
19:52:43.179 (2179741751)|USER_DEBUG|[16]|DEBUG|acc fin 597
19:52:44.133 (3133544554)|USER_DEBUG|[2]|DEBUG|acc init 826
19:52:45.170 (4170227972)|USER_DEBUG|[14]|DEBUG|time spent 279
19:52:45.170 (4170304173)|USER_DEBUG|[16]|DEBUG|acc fin 1105
19:52:46.084 (5084796209)|USER_DEBUG|[2]|DEBUG|acc init 1329
19:52:47.172 (6172788627)|USER_DEBUG|[14]|DEBUG|time spent 274
19:52:47.172 (6172865259)|USER_DEBUG|[16]|DEBUG|acc fin 1603
19:52:48.118 (7118425678)|USER_DEBUG|[2]|DEBUG|acc init 1826
19:52:49.174 (8174007284)|USER_DEBUG|[14]|DEBUG|time spent 285
19:52:49.174 (8174084380)|USER_DEBUG|[16]|DEBUG|acc fin 2111
19:52:50.111 (9111138375)|USER_DEBUG|[2]|DEBUG|acc init 2332
19:52:51.204 (10204845160)|USER_DEBUG|[14]|DEBUG|time spent 283
19:52:51.204 (10204921500)|USER_DEBUG|[16]|DEBUG|acc fin 2615
19:52:51.260 (10260109318)|USER_DEBUG|[9]|DEBUG|fin 2661

Run 3
19:54:02.027 (27239212)|USER_DEBUG|[1]|DEBUG|init 0
19:54:03.054 (1054953385)|USER_DEBUG|[2]|DEBUG|acc init 305
19:54:04.330 (2330306714)|USER_DEBUG|[14]|DEBUG|time spent 262
19:54:04.330 (2330409781)|USER_DEBUG|[16]|DEBUG|acc fin 567
19:54:05.199 (3199664612)|USER_DEBUG|[2]|DEBUG|acc init 788
19:54:06.289 (4289938817)|USER_DEBUG|[14]|DEBUG|time spent 261
19:54:06.290 (4290011886)|USER_DEBUG|[16]|DEBUG|acc fin 1049
19:54:07.135 (5135378353)|USER_DEBUG|[2]|DEBUG|acc init 1267
19:54:08.270 (6270384774)|USER_DEBUG|[14]|DEBUG|time spent 265
19:54:08.270 (6270456992)|USER_DEBUG|[16]|DEBUG|acc fin 1532
19:54:09.092 (7092657115)|USER_DEBUG|[2]|DEBUG|acc init 1754
19:54:10.084 (8084727358)|USER_DEBUG|[14]|DEBUG|time spent 253
19:54:10.084 (8084801735)|USER_DEBUG|[16]|DEBUG|acc fin 2008
19:54:10.968 (8968060832)|USER_DEBUG|[2]|DEBUG|acc init 2220
19:54:11.943 (9943200926)|USER_DEBUG|[14]|DEBUG|time spent 248
19:54:11.943 (9943272647)|USER_DEBUG|[16]|DEBUG|acc fin 2469
19:54:11.994 (9994630081)|USER_DEBUG|[9]|DEBUG|fin 2512

I get the question-- are formulas evaluated only until they are proven false (lazy evaluation) — sfdcfox, Jul 3, 2015 at 3:05
Exactly @sfdcfox. I've added another test turn which doesn't really answer. I guess I better add more workflows & validations. — dzh, Jul 3, 2015 at 3:09
It would seem that to learn anything of significance, you'd want a large sample size of say 200 to preferably something more like at least 1000 or more records (depends on the size of your org). A single record to say 5 will tell you very little of statistical significance. — crmprogdev, Jul 3, 2015 at 12:59
@crmprogdev, Good point, although I was hoping to see results earlier. After running tests with 1k records and 15 workflows, 6 validation rules I still have somewhat vague results: 2965 vs 3101 ms run times (correct vs incorrect version). Occasionally differences are larger and sometimes results are opposite. So no clear answer here. — dzh, Jul 6, 2015 at 2:48

Community · Accepted Answer · 2020-06-15 08:11:08Z

I took a crack at figuring this one out.

To help cut down on noise, I tried to use the most onerous (and least useful) validation rule I could come up with. My hope with this was that I'd be able to get a clear and at least somewhat significant result with a small sample size.

(
  BEGINS(Opportunity__r.Account.Owner.Profile.LastModifiedById, '005') &&
  BEGINS(Opportunity__r.Account.Owner.Profile.LastModifiedById, '005') &&
  BEGINS(Opportunity__r.Account.Owner.Profile.LastModifiedById, '005') &&
                        ...repeated 46 times...
  BEGINS(Opportunity__r.Account.Owner.Profile.LastModifiedById, '005') &&
)

I ran

3 test sets,
10 iterations of each set (well...16 of the first set, 11 of the second, and 10 of the third.)
each iteration attempting to insert 10 records (which have a lookup relationship to Opportunity)

Data points were collected from the Millis column of the Analysis perspective in the Developer Console. I assume this has some correlation to the CPU Time governor limit.

My log levels were:

DB: INFO, Callouts: INFO, ApexCode: DEBUG, Validation: FINEST, Workflow: INFO, Profiling: FINEST, Visualforce: INFO, System: DEBUG

I used the above validation rule as a base. Each test set modified this base validation rule in one single way.

I assume the distribution of results in all test sets is Gaussian.

test set 1 ran the following validation rule:

true && (
  BEGINS(Opportunity__r.Account.Owner.Profile.LastModifiedById, '005') &&
  BEGINS(Opportunity__r.Account.Owner.Profile.LastModifiedById, '005') &&
  BEGINS(Opportunity__r.Account.Owner.Profile.LastModifiedById, '005') &&
                        ...repeated 46 times...
  BEGINS(Opportunity__r.Account.Owner.Profile.LastModifiedById, '005') &&
)

test set 2 ran the following validation rule:

false && (
  BEGINS(Opportunity__r.Account.Owner.Profile.LastModifiedById, '005') &&
  BEGINS(Opportunity__r.Account.Owner.Profile.LastModifiedById, '005') &&
  BEGINS(Opportunity__r.Account.Owner.Profile.LastModifiedById, '005') &&
                        ...repeated 46 times...
  BEGINS(Opportunity__r.Account.Owner.Profile.LastModifiedById, '005') &&
)

test set 3 ran the following validation rule:

(
  BEGINS(Opportunity__r.Account.Owner.Profile.LastModifiedById, '005') &&
  BEGINS(Opportunity__r.Account.Owner.Profile.LastModifiedById, '005') &&
  BEGINS(Opportunity__r.Account.Owner.Profile.LastModifiedById, '005') &&
                        ...repeated 46 times...
  BEGINS(Opportunity__r.Account.Owner.Profile.LastModifiedById, '005') &&
) && false

The validation rule in the first test set will always fail (i.e. the validation formula result is true), and needs to evaluate every part of the formula.

The validation rule in the second test set will always pass, and does not need to evaluate every part of the formula (if formulas use short-circuit evaluation), but may still evaluate every part of the formula.

The validation rule in the second test will always pass, but will need to evaluate every part of the formula (as the determining factor is at the tail of the formula).

My results were as follows

Test set 1:

25.99, 24.62, 25.62, 29.19, 24.63, 25.20, 26.12, 24.74, 29.80, 23.64, 24.17, 24.91, 23.40, 32.67, 30.25, 29.19

Avg: 26.50875, Std Dev: 2.78372, Variance: 7.74912

Test set 2:

18.81, 17.65, 18.84, 17.81, 17.38, 17.99, 18.61, 19.25, 17.37, 17.42, 18.41

Avg: 18.14, Std Dev: 0.6727, Variance: 0.45252

Test set 3:

24.90, 27.75, 23.68, 24.04, 28.36, 24.27, 24.65, 24.60, 24.69, 23.31

Avg: 25.025, Std Dev: 1.67622, Variance: 2.80972

The data from test set 3 is quite like the data from test set 1, and very much unlike the data from test set 2. 3 standard deviations above the average for test set 2 is 20.1581 3 standard deviations below the average for test set 3 is 19.99634

From this I think I can draw the following conclusions:

Validation rule formulas are evaluated lazily
Validation rule formulas use short-circuit evaluation
If you have a condition that has a higher chance of being able to short-circuit the rest of the formula, put it towards the beginning of your formula

The sample sizes are very small, so take that into consideration as well.

In my experience though, validation rules don't start to be a significant contribution to the CPU Time limit until you start working with thousands of records in a single execution context.

My apologies to any statisticians out there reading this, as I probably murdered statistical analysis.

Stack Exchange Network

Formulas in workflows & validation - lazy or eager evaluated?

1 Answer 1

You must log in to answer this question.

Not the answer you're looking for? Browse other questions tagged
workflow
validation
performance
cpulimit
.

Linked

Hot Network Questions

Formulas in workflows & validation - lazy or eager evaluated?

1 Answer 1

You must log in to answer this question.

Not the answer you're looking for? Browse other questions tagged workflowvalidationperformancecpulimit.

Linked

Related

Hot Network Questions

Not the answer you're looking for? Browse other questions tagged
workflow
validation
performance
cpulimit
.