Refactor #2630

Sourced files are checksummed twice

Added by Josh Anderson over 2 years ago. Updated 20 days ago.

Status:Closed Start date:09/13/2009
Priority:Normal Due date:
Assignee:- % Done:

0%
Category:file
Target version:2.7.x
Affected Puppet version:0.25.0 Branch:
Keywords:
Votes: 4

Description

Sourced files are being checksummed twice, doubling the processing time for these resources. This really adds up if you have a lot of files (or a few large files).

To see for yourself, add a puts or debug call to the checksum_file function in util/checksums.rb:

    def checksum_file(digest, filename, lite = false)
        puts "DEBUG: checksumming %s" % filename

Stack traces generated from checksum_file show that it’s being called from both /type/file/content.rb and type/file/checksum.rb. Here’s a sample run with stack traces:

# puppetd --no-daemonize --verbose --onetime --tags filetest
notice: Ignoring --listen on onetime run
info: Retrieving plugin
DEBUG: checksumming /var/puppet/lib/facter/servertype.rb
DEBUG: checksumming /var/puppet/lib/facter/serverenv.rb
DEBUG: checksumming /var/puppet/lib/facter/mailstore.rb
DEBUG: checksumming /var/puppet/lib/facter/macosx_minorversion.rb
DEBUG: checksumming /var/puppet/lib/facter/servernet.rb
DEBUG: checksumming /var/puppet/lib/facter/zonename.rb
DEBUG: checksumming /var/puppet/lib/facter/sparseroot.rb
DEBUG: checksumming /var/puppet/lib/facter/imsversion.rb
DEBUG: checksumming /var/puppet/lib/facter/servertype.rb
DEBUG: checksumming /var/puppet/lib/facter/serverenv.rb
DEBUG: checksumming /var/puppet/lib/facter/mailstore.rb
DEBUG: checksumming /var/puppet/lib/facter/macosx_minorversion.rb
DEBUG: checksumming /var/puppet/lib/facter/servernet.rb
DEBUG: checksumming /var/puppet/lib/facter/zonename.rb
DEBUG: checksumming /var/puppet/lib/facter/sparseroot.rb
DEBUG: checksumming /var/puppet/lib/facter/imsversion.rb
DEBUG: checksumming /var/puppet/lib/facter/imsversion.rb
DEBUG: checksumming /var/puppet/lib/facter/imsversion.rb
DEBUG: checksumming /var/puppet/lib/facter/macosx_minorversion.rb
DEBUG: checksumming /var/puppet/lib/facter/macosx_minorversion.rb
DEBUG: checksumming /var/puppet/lib/facter/mailstore.rb
DEBUG: checksumming /var/puppet/lib/facter/mailstore.rb
DEBUG: checksumming /var/puppet/lib/facter/serverenv.rb
DEBUG: checksumming /var/puppet/lib/facter/serverenv.rb
DEBUG: checksumming /var/puppet/lib/facter/servernet.rb
DEBUG: checksumming /var/puppet/lib/facter/servernet.rb
DEBUG: checksumming /var/puppet/lib/facter/servertype.rb
DEBUG: checksumming /var/puppet/lib/facter/servertype.rb
DEBUG: checksumming /var/puppet/lib/facter/sparseroot.rb
DEBUG: checksumming /var/puppet/lib/facter/sparseroot.rb
DEBUG: checksumming /var/puppet/lib/facter/zonename.rb
DEBUG: checksumming /var/puppet/lib/facter/zonename.rb
info: Loading facts in imsversion
info: Loading facts in macosx_minorversion
info: Loading facts in mailstore
info: Loading facts in serverenv
info: Loading facts in servernet
info: Loading facts in servertype
info: Loading facts in sparseroot
info: Loading facts in zonename
info: Loading facts in macosx_minorversion
info: Loading facts in imsversion
info: Loading facts in servertype
info: Loading facts in mailstore
info: Loading facts in serverenv
info: Loading facts in servernet
info: Loading facts in sparseroot
info: Loading facts in zonename
info: Loading facts in imsversion
info: Loading facts in macosx_minorversion
info: Loading facts in mailstore
info: Loading facts in serverenv
info: Loading facts in servernet
info: Loading facts in servertype
info: Loading facts in sparseroot
info: Loading facts in zonename
info: Loading facts in macosx_minorversion
info: Loading facts in imsversion
info: Loading facts in servertype
info: Loading facts in mailstore
info: Loading facts in serverenv
info: Loading facts in servernet
info: Loading facts in sparseroot
info: Loading facts in zonename
info: Caching catalog for puppetm.foo.com
info: Applying configuration version '1252622612'
DEBUG: checksumming /var/tmp/test.tar
#
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/util/checksums.rb:79:in `/'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/util/checksums.rb:79:in `checksum_file'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/util/checksums.rb:29:in `md5_file'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/type/file/checksum.rb:153:in `send'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/type/file/checksum.rb:153:in `getsum'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/type/file/checksum.rb:216:in `retrieve'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/type.rb:810:in `currentpropvalues'
/opt/ruby/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:31:in `inject'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/type.rb:802:in `each'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/type.rb:802:in `inject'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/type.rb:802:in `currentpropvalues'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/type.rb:790:in `retrieve'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/type/file.rb:638:in `retrieve'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/type.rb:719:in `evaluate'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/transaction.rb:60:in `apply'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/transaction.rb:249:in `eval_children_and_apply_resource'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/util.rb:422:in `thinmark'
/opt/ruby/lib/ruby/1.8/benchmark.rb:308:in `realtime'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/util.rb:421:in `thinmark'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/transaction.rb:248:in `eval_children_and_apply_resource'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/transaction.rb:205:in `eval_resource'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/transaction.rb:294:in `evaluate'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/util.rb:422:in `thinmark'
/opt/ruby/lib/ruby/1.8/benchmark.rb:308:in `realtime'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/util.rb:421:in `thinmark'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/transaction.rb:293:in `evaluate'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/transaction.rb:287:in `collect'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/transaction.rb:287:in `evaluate'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/resource/catalog.rb:139:in `apply'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/configurer.rb:147:in `run'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/util.rb:177:in `benchmark'
/opt/ruby/lib/ruby/1.8/benchmark.rb:308:in `realtime'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/util.rb:176:in `benchmark'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/configurer.rb:146:in `run'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/agent.rb:53:in `run'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/agent/locker.rb:21:in `lock'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/agent.rb:53:in `run'
/opt/ruby/lib/ruby/1.8/sync.rb:230:in `synchronize'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/agent.rb:53:in `run'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/agent.rb:130:in `with_client'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/agent.rb:51:in `run'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/application/puppetd.rb:103:in `onetime'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/application.rb:226:in `send'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/application.rb:226:in `run_command'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/application.rb:217:in `run'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/application.rb:306:in `exit_on_fail'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/application.rb:217:in `run'
/usr/bin/puppetd:159
DEBUG: checksumming /var/tmp/test.tar
#
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/util/checksums.rb:79:in `/'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/util/checksums.rb:79:in `checksum_file'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/util/checksums.rb:29:in `md5_file'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/type/file/content.rb:122:in `send'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/type/file/content.rb:122:in `retrieve'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/type.rb:810:in `currentpropvalues'
/opt/ruby/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:31:in `inject'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/type.rb:802:in `each'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/type.rb:802:in `inject'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/type.rb:802:in `currentpropvalues'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/type.rb:790:in `retrieve'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/type/file.rb:638:in `retrieve'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/type.rb:719:in `evaluate'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/transaction.rb:60:in `apply'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/transaction.rb:249:in `eval_children_and_apply_resource'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/util.rb:422:in `thinmark'
/opt/ruby/lib/ruby/1.8/benchmark.rb:308:in `realtime'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/util.rb:421:in `thinmark'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/transaction.rb:248:in `eval_children_and_apply_resource'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/transaction.rb:205:in `eval_resource'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/transaction.rb:294:in `evaluate'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/util.rb:422:in `thinmark'
/opt/ruby/lib/ruby/1.8/benchmark.rb:308:in `realtime'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/util.rb:421:in `thinmark'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/transaction.rb:293:in `evaluate'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/transaction.rb:287:in `collect'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/transaction.rb:287:in `evaluate'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/resource/catalog.rb:139:in `apply'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/configurer.rb:147:in `run'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/util.rb:177:in `benchmark'
/opt/ruby/lib/ruby/1.8/benchmark.rb:308:in `realtime'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/util.rb:176:in `benchmark'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/configurer.rb:146:in `run'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/agent.rb:53:in `run'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/agent/locker.rb:21:in `lock'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/agent.rb:53:in `run'
/opt/ruby/lib/ruby/1.8/sync.rb:230:in `synchronize'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/agent.rb:53:in `run'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/agent.rb:130:in `with_client'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/agent.rb:51:in `run'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/application/puppetd.rb:103:in `onetime'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/application.rb:226:in `send'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/application.rb:226:in `run_command'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/application.rb:217:in `run'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/application.rb:306:in `exit_on_fail'
/opt/ruby/lib/ruby/site_ruby/1.8/puppet/application.rb:217:in `run'
/usr/bin/puppetd:159
DEBUG: checksumming /var/tmp/blah/g.txt
DEBUG: checksumming /var/tmp/blah/a.txt
DEBUG: checksumming /var/tmp/blah/d.txt
DEBUG: checksumming /var/tmp/blah/b.txt
DEBUG: checksumming /var/tmp/blah/e.txt
DEBUG: checksumming /var/tmp/blah/c.txt
DEBUG: checksumming /var/tmp/blah/f.txt
DEBUG: checksumming /var/tmp/blah/g.txt
DEBUG: checksumming /var/tmp/blah/a.txt
DEBUG: checksumming /var/tmp/blah/d.txt
DEBUG: checksumming /var/tmp/blah/b.txt
DEBUG: checksumming /var/tmp/blah/e.txt
DEBUG: checksumming /var/tmp/blah/c.txt
DEBUG: checksumming /var/tmp/blah/f.txt
notice: Finished catalog run in 10.65 seconds

Please note that stack traces were only generated for one sourced file in the test module.

It seems like this double checksumming could be eliminated with some clever refactoring. Checksum.rb already caches the value it generates (and source.rb uses that value), but content.rb is calling <checksum type>_file directly rather than asking for the value of the checksum parameter.

Related issues

related to Puppet - Bug #2929: File rucurse true, checksums all the files with md5 Closed 12/14/2009

History

#1
Updated by James Turnbull over 2 years ago

  • Status changed from Unreviewed to Accepted
  • Target version set to 0.25.1

#2
Updated by Brice Figureau over 2 years ago

Josh Anderson wrote:

Please note that stack traces were only generated for one sourced file in the test module.

Which I think has size 0 (this is a wild guess I didn’t look at the code). We should also protect against div by 0 in this code…

#3
Updated by Josh Anderson over 2 years ago

Brice Figureau wrote:

Josh Anderson wrote:

Please note that stack traces were only generated for one sourced file in the test module.

Which I think has size 0 (this is a wild guess I didn’t look at the code). We should also protect against div by 0 in this code…

No, that was just me throwing an exception so I could generate a stack trace. Lame, but it works.

#4
Updated by Markus Roberts over 2 years ago

A clear way to generate this:

node default {
    file{"/tmp/ticket_2630_file":
            content = "this is for ticket 2630"
    }
}

Run one, tamper with the file and run again results in:

info: Caching catalog for boohoo
info: Applying configuration version '1253047725'
notice: //Node[default]/File[/tmp/ticket_2630_file]/checksum: checksum changed '{md5}8676a5a4d8b13c9ddee9b6b163561d7b' to '{md5}b04d2d9913e7e8d9866a57bfc4e830e8'
info: //Node[default]/File[/tmp/ticket_2630_file]: Filebucketed /tmp/ticket_2630_file to puppet with sum b04d2d9913e7e8d9866a57bfc4e830e8
notice: //Node[default]/File[/tmp/ticket_2630_file]/content: content changed '{md5}b04d2d9913e7e8d9866a57bfc4e830e8' to '{md5}8676a5a4d8b13c9ddee9b6b163561d7b'
notice: Finished catalog run in 0.13 seconds

#5
Updated by Markus Roberts over 2 years ago

  • Target version changed from 0.25.1 to 2.6.0

Luke points out that there are two basic ways to solve this: either kludge in a way to cache the checksum or do the actual refactoring needed to disentangle the use of content v. checksum. The later is the better option.

By the present criteria this is outside of the scope of 0.25.1 and should be targeted for 0.26.

#6
Updated by Markus Roberts about 2 years ago

  • Assignee set to Markus Roberts

#7
Updated by James Turnbull about 2 years ago

  • Target version changed from 2.6.0 to 2.7.x

#8
Updated by Joshua Lifton about 1 month ago

  • Assignee deleted (Markus Roberts)

This issue was assigned to a former Puppet Labs employee. Adding back to the pool of unreviewed issues.

#9
Updated by Joshua Lifton about 1 month ago

This issue was assigned to a former Puppet Labs employee. Adding back to the pool of unreviewed issues.

#10
Updated by Ben Hughes 21 days ago

  • Description updated (diff)
  • Status changed from Accepted to Unreviewed

#11
Updated by Luke Kanies 20 days ago

  • Description updated (diff)
  • Status changed from Unreviewed to Closed

It looks like this is fixed. I thought my work in 2.7 might have done so, and I’ve just confirmed in my own testing that I don’t see two checksums.

Also available in: Atom PDF