Software Environment
查看 /proc/cpuinfo
BogoMIPS : 712.70
查看 /proc/meminfo
MemTotal: 251440 kB
测试项1
1.Disable Findme
启动瞬间CPU 接近90%-100%, thin start/stop等命令占用特别高
稳定以后, CPU 17%,MEM 17% thin Server
稳定以后,CPU 0%, MEM 13.5% Ruby Downloader(无下载任务)
2. Enable Findme
稳定以后, CPU 在12%-40%跳动,MEM 17% thin Server
稳定以后,CPU 0%, MEM 13.5% Ruby Downloader(无下载任务)
让Findme 间隔为1s, CPU 在12%-40%跳动，但是20%-40%较多，貌似负载heavier了一些
Ruby Downloader无变化
打开admin/configuration页面，Thin Server和Ruby Downloader均未见明显变化
(admin/configuration有不断的向server query status)
3.进行unicast通话
thin cpu到7%-23%,mem基本无变化(cpu至少超过2s会跳0%)
ruby downloader基本无变化
linphone cpu 上涨到4%-7%(原来接近0%）, mem到3%-4%(原来也差不多2%-3%)
4.如果打开conference对话,邀请2个人,
thin cpu到7%-23%,mem基本无变化(cpu至少超过2s会跳0%)
怀疑上涨的cpu主要是多了几个call的运算(phone.rb里头@calls这个Hash)以及返回界面结果造成上涨
ruby downloader基本无变化
linphone cpu 上涨到4%-7%(原来接近0%）, mem到3%-4%(原来也差不多2%-3%)
(邀请4个人基本也差不多)
5.广播邀请2个人,与conference基本一致
thin cpu到7%-23%,mem基本无变化(cpu至少超过2s会跳0%)
ruby downloader基本无变化
linphone cpu 上涨到4%-7%(原来接近0%）, mem到3%-4%(原来也差不多2%-3%)
(邀请4个人基本也差不多,也与conference基本一致)
6.先1010拨打某个电话,然后1002以高优先级用户进来广播1010
数据基本一致，无太大变化。
7.一旦开始下载,
如果server puma不打开，基本数据一致，
但是如果server puma打开,ruby downloader cpu
上到40%-57%, MEM 16.4%
说明该段代码比较占用cpu
8.打开Profile,对downloader profiling
RACK_ENV=production ruby downloader.rb |more
Thread ID: 854292
Total: 2.825563
Sort by: self_time
%self total self wait child calls name
32.52 0.95 0.92 0.00 0.03 975 Module#module_eval
24.24 0.70 0.68 0.00 0.02 23 *Kernel#require_without_backports
21.09 0.60 0.60 0.00 0.00 400 SQLite3::Statement#initialize
17.89 0.68 0.51 0.00 0.18 670 #relation
17.01 0.57 0.48 0.00 0.09 1513 SQLite3::Statement#step
15.52 0.57 0.44 0.00 0.13 339 ActiveRecord::QueryMethods#build_where
13.08 0.37 0.37 0.00 0.00 372 String#slice!
10.54 0.30 0.30 0.00 0.01 1 #instrumenter
6.98 0.23 0.20 0.00 0.03 4334 Kernel#respond_to?
6.63 0.19 0.19 0.00 0.00 1973 #logger
6.35 2.16 0.18 0.00 1.98 7249 *Class#new
5.99 0.17 0.17 0.00 0.00 2405 Module#method_defined?
5.70 0.33 0.16 0.00 0.17 800 Array#initialize
5.63 3.08 0.16 0.00 2.92 701 ActiveSupport::Notifications::Instrumenter#instrument
5.50 1.56 0.16 0.00 1.41 658 ActiveRecord::QueryMethods#build_arel
5.43 0.15 0.15 0.00 0.00 10984 Kernel#class
5.34 0.15 0.15 0.00 0.00 11776 #current
5.18 0.15 0.15 0.00 0.00 5233 Thread#[]
4.82 0.31 0.14 0.00 0.18 1355 ActiveSupport::Callbacks::ClassMethods#__callback_runner_name
4.76 0.13 0.13 0.00 0.00 8720 Module#===
4.67 1.47 0.13 0.00 1.34 640 Arel::Visitors::ToSql#visit_Arel_Nodes_SelectCore
4.60 -2.46 0.13 0.00 -2.59 938 *ActiveRecord::Scoping::ClassMethods#with_scope
4.50 0.13 0.13 0.00 0.00 5214 Array#join
4.33 -0.64 0.12 0.00 -0.77 636 ActiveRecord::Relation#exec_queries
4.23 0.23 0.12 0.00 0.11 302 ActiveRecord::ConnectionAdapters::Quoting#type_cast
4.23 0.12 0.12 0.00 0.00 4964 Module#name
4.22 0.12 0.12 0.00 0.00 7133 #allocate
4.00 -0.57 0.11 0.00 -0.69 640 ActiveRecord::Base#init_with
3.96 0.11 0.11 0.00 0.00 4870 Regexp#===
3.92 3.98 0.11 0.00 3.87 1355 *ActiveSupport::Callbacks::ClassMethods#__run_callback
3.85 0.42 0.11 0.19 0.12 1880 ActiveRecord::Scoping::ClassMethods#current_scope
3.80 0.11 0.11 0.00 0.00 7557 Kernel#hash
3.71 0.44 0.10 0.00 0.34 637 ActiveModel::AttributeMethods::ClassMethods#define_optimized_call
8.
192.168.11.221:9090
downloading #
Thread ID: 854292
Total: 2.121540
Sort by: self_time
%self total self wait child calls name
444.00 9.52 9.42 0.00 0.10 1457 SQLite3::Statement#step
49.56 1.09 1.05 0.00 0.04 975 Module#module_eval
32.82 0.71 0.70 0.00 0.02 23 *Kernel#require_without_backports
24.97 0.70 0.53 0.00 0.17 640 #relation
23.57 0.50 0.50 0.00 0.00 343 SQLite3::Statement#initialize
18.47 0.39 0.39 0.00 0.00 394 String#slice!
15.92 0.47 0.34 0.00 0.14 319 ActiveRecord::QueryMethods#build_where
14.58 0.32 0.31 0.00 0.01 1 #instrumenter
10.88 0.23 0.23 0.00 0.00 1922 #logger
9.50 0.23 0.20 0.00 0.03 4115 Kernel#respond_to?
7.61 1.93 0.16 0.00 1.77 6658 *Class#new
7.22 7.28 0.15 0.00 7.13 654 ActiveSupport::Notifications::Instrumenter#instrument
7.20 4.30 0.15 0.00 4.14 947 *ActiveRecord::Scoping::ClassMethods#with_scope
7.18 0.15 0.15 0.00 0.00 5115 Thread#[]
7.05 1.52 0.15 0.00 1.37 637 ActiveRecord::QueryMethods#build_arel
7.00 0.15 0.15 0.00 0.00 11513 #current
6.60 -0.16 0.14 0.00 -0.30 634 ActiveRecord::Base#init_with
6.56 0.29 0.14 0.00 0.15 686 Array#initialize
6.40 0.14 0.14 0.00 0.00 8319 Module#===
6.25 0.26 0.13 0.00 0.13 1895 ActiveRecord::Scoping::ClassMethods#current_scope
6.25 -2.79 0.13 0.00 -2.92 634 Arel::Visitors::ToSql#visit_Arel_Nodes_SelectCore
6.19 0.13 0.13 0.00 0.00 5107 Array#join
6.18 0.13 0.13 0.00 0.00 9852 Kernel#class
5.95 0.26 0.13 0.00 0.13 634 ActiveRecord::Relation#exec_queries
5.83 0.55 0.12 0.00 0.43 637 ActiveModel::AttributeMethods::ClassMethods#define_optimized_call
5.81 0.28 0.12 0.00 0.16 1274 ActiveSupport::Callbacks::ClassMethods#__callback_runner_name
5.56 -3.65 0.12 0.00 -3.77 910 ActiveRecord::AttributeMethods::ClassMethods#instance_method_already_implemented?
5.51 0.12 0.12 0.00 0.00 4731 Module#name
5.39 0.11 0.11 0.00 0.00 4756 Regexp#===
5.35 0.17 0.11 0.00 0.05 634 ActiveRecord::Inheritance::ClassMethods#instantiate
5.14 0.33 0.11 0.10 0.12 1893 ActiveRecord::Scoping::ClassMethods#current_scope=
4.95 -0.40 0.10 0.00 -0.50 1274 *ActiveSupport::Callbacks#run_callbacks
4.93 0.47 0.10 0.00 0.37 951 Arel::Visitors::ToSql#visit_Arel_Attributes_Attribute
4.91 0.10 0.10 0.00 0.00 6682 #allocate
4.69 0.24 0.10 0.00 0.14 2594 *ActiveRecord::ConnectionAdapters::ConnectionHandler#retrieve_connection_pool
time: 27.161111495
Thread ID: 13598700
Total: 0.152082
Sort by: self_time
%self total self wait child calls name
27.44 0.04 0.04 0.00 0.00 147 Module#module_eval
called from: #delegate_to_scoped_klass (/home/c2h2/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/activerecord-3.2.8/lib/active_record/relation/delegation.rb:10) ActiveRecord::AttributeMethods::Read::ClassMethods#define_method_attribute (/home/c2h2/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/activerecord-3.2.8/lib/active_record/attribute_methods/read.rb:69) ActiveRecord::AttributeMethods::Write::ClassMethods#define_method_attribute= (/home/c2h2/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/activerecord-3.2.8/lib/active_record/attribute_methods/write.rb:12) ActiveModel::AttributeMethods::ClassMethods#define_optimized_call (/home/c2h2/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/activemodel-3.2.8/lib/active_model/attribute_methods.rb:328) ActiveRecord::AttributeMethods::Read::ClassMethods#define_external_attribute_method (/home/c2h2/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/activerecord-3.2.8/lib/active_record/attribute_methods/read.rb:81)
21.64 0.08 0.03 0.00 0.04 15 #relation
/home/c2h2/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/activerecord-3.2.8/lib/active_record/base.rb:452
called from: ActiveRecord::Scoping::Named::ClassMethods#scoped (/home/c2h2/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/activerecord-3.2.8/lib/active_record/scoping/named.rb:30)
3.21 0.01 0.00 0.00 0.00 17 *Kernel#require_without_backports
called from: Kernel#require_with_backports (/home/c2h2/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/backports-2.6.4/lib/backports/tools.rb:312)
1.80 0.00 0.00 0.00 0.00 21 SQLite3::Statement#initialize
called from:
1.46 0.00 0.00 0.00 0.00 1 #instrumenter
/home/c2h2/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/activesupport-3.2.8/lib/active_support/notifications.rb:147
called from: ActiveRecord::ConnectionAdapters::AbstractAdapter#initialize (/home/c2h2/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/activerecord-3.2.8/lib/active_record/connection_adapters/abstract_adapter.rb:60)
0.99 0.07 0.00 0.00 0.07 283 *Array#each
called from: Module#delegate (/home/c2h2/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/activesupport-3.2.8/lib/active_support/core_ext/module/delegation.rb:104) ActiveSupport::Concern#append_features (/home/c2h2/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/activesupport-3.2.8/lib/active_support/concern.rb:105) ActiveSupport::Inflector#apply_inflections (/home/c2h2/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/activesupport-3.2.8/lib/active_support/inflector/methods.rb:310) ActiveRecord::Relation#initialize (/home/c2h2/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/activerecord-3.2.8/lib/active_record/relation.rb:19) ActiveSupport::Callbacks::CallbackChain#compile (/home/c2h2/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:346) ActiveSupport::Notifications::Fanout#publish (/home/c2h2/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/activesupport-3.2.8/lib/active_support/notifications/fanout.rb:24) ActiveRecord::Result#each (/home/c2h2/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/activerecord-3.2.8/lib/active_record/result.rb:19) ActiveRecord::QueryMethods#collapse_wheres (/home/c2h2/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/activerecord-3.2.8/lib/active_record/relation/query_methods.rb:310) ActiveModel::AttributeMethods::ClassMethods#define_attribute_methods (/home/c2h2/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/activemodel-3.2.8/lib/active_model/attribute_methods.rb:255) ActiveModel::AttributeMethods::ClassMethods#define_attribute_method (/home/c2h2/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/activemodel-3.2.8/lib/active_model/attribute_methods.rb:259) Mutex#synchronize (/home/c2h2/rails-project/luna-client/:7) ActiveRecord::Relation#exec_queries (/home/c2h2/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/activerecord-3.2.8/lib/active_record/relation.rb:164) Hash#except! (/home/c2h2/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/activesupport-3.2.8/lib/active_support/core_ext/hash/except.rb:19) Arel::Visitors::DepthFirst#visit_Array (/home/c2h2/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/arel-3.0.2/lib/arel/visitors/depth_first.rb:158) Downloader#download_all (/home/c2h2/rails-project/luna-client/downloader.rb:96)
0.98 0.01 0.00 0.00 0.01 21 ActiveSupport::Notifications::Instrumenter#instrument
/home/c2h2/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/activesupport-3.2.8/lib/active_support/notifications/instrumenter.rb:16
called from: ActiveRecord::ConnectionAdapters::AbstractAdapter#log (/home/c2h2/.rbenv/versions/1.9.3-p194/lib/ruby/gems/1.9.1/gems/activerecord-3.2.8/lib/active_record/connection_adapters/abstract_adapter.rb:274)
0.95 0.00 0.00 0.00 0.00 766 Regexp#===
9.使用benchmark measure,代码如下
result = Benchmark.measure do
1000.times do |i|
#puts TimeRange.all
#puts DB[:time_ranges].all
puts ActiveRecord::Base.connection.execute("select * from time_ranges")
end
end
puts result
运行结果，
第一次
ActiveRecord::Base.connection.execute 0.140000 0.180000 0.320000 ( 0.318782)
TimeRange.all 0.290000 0.270000 0.560000 ( 0.602421)
DB[:time_ranges] 0.370000 0.310000 0.680000 ( 0.688747)
第二次
ActiveRecord::Base.connection.execute 0.100000 0.220000 0.320000 ( 0.323874)
TimeRange.all 0.330000 0.230000 0.560000 ( 0.574226)
DB[:time_ranges].all 0.210000 0.270000 0.480000 ( 0.491112)
使用Profile对测试用例进行测试:
ActiveRecord TimeRange.all:
time: 2.315390923
Thread ID: 19572720
Total: 2.272612
Sort by: self_time
%self total self wait child calls name
5.32 0.12 0.12 0.00 0.00 1003 SQLite3::Statement#initialize
3.05 0.09 0.07 0.00 0.02 3006 Time#initialize
2.84 0.07 0.06 0.00 0.01 2030 SQLite3::Statement#step
2.39 0.05 0.05 0.00 0.00 6006 #logger
2.12 0.10 0.05 0.00 0.05 2006 Array#initialize
2.09 1.04 0.05 0.00 0.99 1003 ActiveSupport::Notifications::Instrumenter#instrument
1.87 0.06 0.04 0.00 0.02 1000 Time#strftime
1.36 0.43 0.03 0.00 0.40 10035 *Class#new
1.35 0.03 0.03 0.00 0.00 3130 String#%
1.28 0.03 0.03 0.00 0.00 13013 SQLite3::Statement#column_name
1.26 0.35 0.03 0.00 0.32 1003 ActiveRecord::LogSubscriber#sql
1.16 0.55 0.03 0.00 0.52 12038 *Array#each
1.14 0.03 0.03 0.00 0.00 17021 #current
1.03 0.18 0.02 0.00 0.16 1000 ActiveRecord::QueryMethods#build_arel
0.98 0.02 0.02 0.00 0.00 3006 #allocate
0.94 0.10 0.02 0.00 0.08 2003 MonitorMixin#mon_synchronize
0.91 2.06 0.02 0.00 2.04 1000 ActiveRecord::Relation#exec_queries
0.90 0.16 0.02 0.00 0.14 1000 Arel::Visitors::ToSql#visit_Arel_Nodes_SelectCore
0.87 0.02 0.02 0.00 0.00 13013 SQLite3::Statement#column_decltype
0.85 0.02 0.02 0.00 0.00 12015 Array#empty?
0.82 0.04 0.02 0.00 0.02 2000 ActiveSupport::Callbacks::ClassMethods#__callback_runner_name
0.81 0.07 0.02 0.00 0.05 1000 ActiveRecord::Scoping::ClassMethods#with_scope
0.77 0.02 0.02 0.00 0.00 3006 Fixnum#+
0.74 0.03 0.02 0.00 0.01 2003 MonitorMixin#mon_enter
0.73 0.06 0.02 0.00 0.05 2000 ActiveRecord::AttributeMethods#respond_to?
0.71 0.04 0.02 0.00 0.02 1000 #relation
0.70 0.03 0.02 0.00 0.01 7002 Enumerable#any?
0.69 0.02 0.02 0.00 0.00 6093 Array#join
0.69 0.02 0.02 0.00 0.00 11035 Kernel#class
0.67 0.02 0.02 0.00 0.00 6009 Thread#[]
0.67 0.02 0.02 0.00 0.00 10 Kernel#require
0.67 0.48 0.02 0.00 0.46 1003 ActiveSupport::LogSubscriber#call
0.66 0.21 0.02 0.00 0.19 1000 ActiveRecord::Base#init_with
0.66 0.02 0.01 0.00 0.00 5136 Kernel#respond_to?
0.64 0.03 0.01 0.00 0.01 2003 MonitorMixin#mon_exit
0.63 0.25 0.01 0.00 0.24 1000 ActiveRecord::Inheritance::ClassMethods#instantiate
0.63 0.11 0.01 0.00 0.09 3006 #now
0.62 0.14 0.01 0.00 0.12 2000 ActiveSupport::Callbacks::ClassMethods#__run_callback
0.62 0.22 0.01 0.00 0.21 1000 Logger#add
0.61 0.20 0.01 0.00 0.19 5100 *Array#map
0.61 0.10 0.01 0.00 0.09 1000 ActiveRecord::Scoping::Named::ClassMethods#scoped
0.59 0.01 0.01 0.00 0.00 7003 Module#===
0.59 0.08 0.01 0.00 0.06 1003 ActiveSupport::Notifications::Event#initialize
0.58 0.16 0.01 0.00 0.15 2000 ActiveSupport::Callbacks#run_callbacks
0.57 0.05 0.01 0.00 0.03 4006 ActiveRecord::LogSubscriber#logger
0.57 0.01 0.01 0.00 0.00 8037 #allocate
0.56 0.04 0.01 0.00 0.03 4000 *ActiveRecord::Scoping::Default::ClassMethods#build_default_scope
0.55 0.19 0.01 0.00 0.17 1000 Arel::Visitors::ToSql#visit_Arel_Nodes_SelectStatement
0.52 0.09 0.01 0.00 0.07 1003 Kernel#loop
0.52 0.01 0.01 0.00 0.00 2000 Kernel#method
0.52 0.01 0.01 0.00 0.00 5508 Kernel#is_a?
0.51 0.01 0.01 0.00 0.00 5041 Module#name
0.49 0.06 0.01 0.00 0.05 1000 Arel::Visitors::ToSql#visit_Arel_Attributes_Attribute
0.48 0.01 0.01 0.00 0.00 5000 Fixnum#*
0.48 2.15 0.01 0.00 2.14 3000 *ActiveRecord::Explain#logging_query_plan
0.48 0.02 0.01 0.00 0.01 1500 ActiveSupport::LogSubscriber#color
0.48 0.02 0.01 0.00 0.01 2000 ActiveRecord::Scoping::ClassMethods#current_scope=
0.48 0.03 0.01 0.00 0.02 1000 Arel::Visitors::ToSql#column_for
0.47 0.03 0.01 0.00 0.02 2000 *ActiveRecord::AttributeMethods::Serialization::ClassMethods#initialize_attributes
0.44 0.02 0.01 0.00 0.01 2000 ActiveRecord::Scoping::ClassMethods#current_scope
0.43 0.01 0.01 0.00 0.00 6006 Kernel#block_given?
0.40 0.02 0.01 0.00 0.01 2000 ActiveRecord::Relation#eager_loading?
0.40 0.06 0.01 0.00 0.05 1000 Arel::SelectManager#initialize
0.40 0.09 0.01 0.00 0.08 1000 Logger::Formatter#format_datetime
0.39 0.12 0.01 0.00 0.11 1000 Logger::Formatter#call
0.39 0.21 0.01 0.00 0.20 4000 *Arel::Visitors::Visitor#visit
0.39 0.06 0.01 0.00 0.05 1000 ActiveRecord::QueryMethods#build_select
0.39 0.02 0.01 0.00 0.01 1000 Arel::Nodes::SelectCore#initialize
0.38 0.01 0.01 0.00 0.00 1003 SQLite3::Statement#close
使用Sequel DB[:time_ranges].all
time: 2.196484471
Thread ID: 8122340
Total: 2.172174
Sort by: self_time
%self total self wait child calls name
4.89 0.94 0.11 0.00 0.83 6004 *Array#each
4.12 0.22 0.09 0.00 0.13 2000 #_parse
4.12 0.09 0.09 0.00 0.00 1002 SQLite3::Statement#initialize
3.78 0.32 0.08 0.00 0.24 3000 Array#map
3.76 0.09 0.08 0.00 0.01 2002 SQLite3::Statement#step
3.42 0.10 0.07 0.00 0.03 2000 #local
3.08 0.15 0.07 0.00 0.08 13000 Sequel::Dataset#output_identifier
2.83 0.08 0.06 0.00 0.02 13000 Sequel::SQLite::Dataset#base_type_name
2.34 0.05 0.05 0.00 0.00 6000 Regexp#match
2.00 0.05 0.04 0.00 0.01 2000 Time#initialize
1.94 0.08 0.04 0.00 0.04 3000 Array#initialize
1.77 0.06 0.04 0.00 0.02 13000 Sequel::Dataset#identifier_output_method
1.63 0.14 0.04 0.00 0.10 2000 #make_time
1.42 0.12 0.03 0.00 0.09 1000 Hash#to_s
1.37 0.03 0.03 0.00 0.00 2000 String#gsub!
1.33 0.07 0.03 0.00 0.04 3000 Mutex#synchronize
1.31 0.03 0.03 0.00 0.00 13000 Symbol#inspect
1.27 0.15 0.03 0.00 0.12 2000 SQLite3::ResultSet#next
1.20 0.39 0.03 0.00 0.36 2000 #parse
使用 ActiveRecord::Base.connection.execute("select * from time_ranges")
time: 1.310823023
Thread ID: 10471400
Total: 1.303938
Sort by: self_time
%self total self wait child calls name
6.12 0.10 0.08 0.00 0.02 3000 Time#initialize
5.95 0.08 0.08 0.00 0.00 1000 SQLite3::Statement#initialize
4.10 0.55 0.05 0.00 0.49 3000 Array#each
3.98 0.06 0.05 0.00 0.00 2000 SQLite3::Statement#step
3.52 0.15 0.05 0.00 0.11 1000 Hash#to_s
3.24 0.08 0.04 0.00 0.04 2000 Array#initialize
3.01 0.06 0.04 0.00 0.02 1000 Time#strftime
2.84 0.07 0.04 0.00 0.03 25000 Kernel#inspect
2.67 0.03 0.03 0.00 0.00 4000 #logger
2.47 0.03 0.03 0.00 0.00 17000 String#inspect
2.22 0.03 0.03 0.00 0.00 25000 Fixnum#to_s
2.03 0.32 0.03 0.00 0.30 1000 ActiveRecord::LogSubscriber#sql
1.88 0.02 0.02 0.00 0.00 13000 SQLite3::Statement#column_name
1.84 0.03 0.02 0.00 0.00 3000 String#%
1.64 0.39 0.02 0.00 0.37 1000 SQLite3::Database#prepare
1.52 1.04 0.02 0.00 1.02 1000 ActiveSupport::Notifications::Instrumenter#instrument
1.34 0.02 0.02 0.00 0.00 13000 Hash#[]=
1.33 0.27 0.02 0.00 0.25 4000 Class#new
1.32 0.02 0.02 0.00 0.00 3000 Fixnum#+
1.31 0.08 0.02 0.00 0.07 2000 MonitorMixin#mon_synchronize
1.30 0.41 0.02 0.00 0.40 1000 SQLite3::Database#execute
1.29 0.46 0.02 0.00 0.45 1000 ActiveSupport::LogSubscriber#call
1.28 0.02 0.02 0.00 0.00 13000 SQLite3::Statement#column_decltype
1.16 0.14 0.02 0.00 0.12 1000 Kernel#loop
1.14 0.12 0.01 0.00 0.10 3000 #now
10.测试磁盘速度
简单测试读速度，使用hdparm简单测试读速度：
虚拟机client:
sudo hdparm -t /dev/sda
/dev/sda:
Timing buffered disk reads: 556 MB in 3.00 seconds = 185.16 MB/sec
sudo hdparm -T /dev/sda
/dev/sda:
Timing cached reads: 8614 MB in 1.98 seconds = 4345.15 MB/sec
对arm机
sudo hdparm -t /dev/mmcblk0p2
/dev/mmcblk0p2:
Timing buffered disk reads: 20 MB in 3.20 seconds = 6.25 MB/sec
sudo hdparm -T /dev/mmcblk0p2
Timing cached reads: 286 MB in 2.01 seconds = 142.53 MB/sec
测试读写同时，使用dd工具:
同时读写，性能显著下降
虚拟机client:
sudo time dd if=/dev/sda1 of=test1.dbf bs=8k count=300000
300000+0 records in
300000+0 records out
2457600000 bytes (2.5 GB) copied, 33.6559 s, 73.0 MB/s
arm机
time dd if=/dev/mmcblk0p2 of=test.dbf bs=8k count=30000
30000+0 records in
30000+0 records out
245760000 bytes (246 MB) copied, 114.915 s, 2.1 MB/s
11.测试多条数据情况：
结果如下,(每个都跑2次)
In memory 10条记录
0.270000 0.300000 0.570000 ( 0.571189) Item.all
0.270000 0.340000 0.610000 ( 0.616333)
0.060000 0.140000 0.200000 ( 0.191373) select * from Items
0.040000 0.140000 0.180000 ( 0.185483)
0.190000 0.010000 0.200000 ( 0.207624) DB[:items]
0.190000 0.000000 0.190000 ( 0.193151)
In memory 1条记录
0.140000 0.140000 0.280000 ( 0.285710) Item.all
0.210000 0.170000 0.380000 ( 0.389182)
0.020000 0.080000 0.100000 ( 0.094184) select * from Item
0.040000 0.090000 0.130000 ( 0.127914)
0.130000 0.000000 0.130000 ( 0.129055) DB[:items]
0.120000 0.000000 0.120000 ( 0.117700)
In disk file 10条记录.
0.400000 0.200000 0.600000 ( 0.605244) Item.all
0.340000 0.280000 0.620000 ( 0.623095)
0.100000 0.150000 0.250000 ( 0.260475) select * from Items
0.070000 0.150000 0.220000 ( 0.221618)
0.210000 0.010000 0.220000 ( 0.216433) DB[:items]
0.210000 0.020000 0.230000 ( 0.233594)
In disk file 1条记录.
0.110000 0.190000 0.300000 ( 0.298891) Item.all
0.150000 0.180000 0.330000 ( 0.331889)
0.010000 0.090000 0.100000 ( 0.108639) select * from Items
0.010000 0.090000 0.100000 ( 0.105636)
0.100000 0.000000 0.100000 ( 0.105770) DB[:items]
0.100000 0.000000 0.100000 ( 0.112484)
In disk file 100
3.300000 0.390000 3.690000 ( 3.698027) Item.all
3.160000 0.480000 3.640000 ( 3.649771)
0.930000 0.280000 1.210000 ( 1.213984) select * from items;
1.040000 0.270000 1.310000 ( 1.305156)
1.090000 0.010000 1.100000 ( 1.108757) DB[:items]
1.070000 0.020000 1.090000 ( 1.083974)