はじめに

タイトルの通り、ログ出力の方法を改善することによって、バッチ実行時間が圧倒的に短くなったのでメモとして残します。実際にログ出力を改善することによって、実行時間が 24.7m -> 14.6m と10分程短くなりました。(これ見たときはかなり驚きましたね..)

改善前

DBアクセス時のデフォルトのログ出力を見てみると、以下のようになっています。

log/development.log

City Load (14.8ms)
	SELECT
		`cities`. *
	FROM
		`cities`
	WHERE
		`cities`.`id` IN (
			1100
			,1203
			,1204
			,1205
			,1206
			,1208
			,1210
			,1213
			,1215
			,1217
			,1219
			,1222
			,1224
			,1226
			,1229
			,1230
			,1231
			,1233
			,1234
			,1235
			,1236
			,1427
			,1607
			,1610
			,1661
			,3201
			,4100
			,5203
			,6202
			,8201
			,8203
			,8204
			,8220
			,8223
			,8440
			,9201
			,9202
			,9203
			,9208
			,9210
			,9213
			,10201
			,10204
			,11100
			,11201
			,11202
			,11203
			,11215
			,11219
			,11221
			,11222
			,11223
			,11224
			,11225
			,11227
			,11229
			,11234
			,11240
			,12100
			,12202
			,12203
			,12204
			,12206
			,12210
			,12211
			,12212
			,12216
			,12217
			,12219
			,12220
			,12224
			,12227
			,13101
			,13102
			,13103
			,13104
			,13105
			,13106
			,13107
			,13108
			,13109
			,13110
			,13111
			,13112
			,13113
			,13114
            ,...(省略)
		)

この状態って実は人が見やすいようにパースされています。
例えば出力対象が100万件とすると、 find_eachで1000件(デフォルト)ずつDBから取ってきた場合、1000回やりますよね。毎回パースして表示するとやはりかなり時間がかかるようです。

改善方法

Gem：rails-flogをインストール

Gemfile

gem 'rails-flog', require: 'flog'

bundlerの実行

$ bundle install

no-flog.txtを作成

$ touch tmp/no-flog.txt

これでパース機能がOFFになります。
非常にシンプルですね。

改善後

MasterCity Load (9.0ms)  SELECT `master_cities`.* FROM `master_cityies` WHERE `master_cities`.`city_id` IN (2, 18, 90, 118, 122, 130, 132, 134, 143, 155, 167, 174, 187, 188, 190, 191, 196, 204, 209, 211, 222, 270, 275, 277, 278, 279, 282, 297, 317, 318, 320, 321, 323, 328, 333, 335, 337, 338, 345, 365, 367, 369, 370, 372, 373, 374, 376, 377, 378, 379, 380, 381, 383, 384, 385, 386, 396, 403, 410, 411, 412, 413, 415, 416, 417, 418, 420, 421, 422, 425, 430, 431, 433, 434, 436, 438, 439, 440, 441, 446, 452, 456, 459, 470, 471, 472, 476, 479, 482, 485, 486, 501, 511, 528, 531, 541, 558, 594, 595, 596, 598, 599, 600, 601, 603, 605, 608, 610, 612, 614, 616, 619, 628, 659, 660, 661, 663, 664, 666, 667, 668, 669, 670, 671, 672, 673, 675, 676, 680, 681, 684, 688, 692, 694, 696, 698, 699, 703, 704, 710, 721, 729, 738, 740, 743, 760, 764, 768, 771, 779, 780, 800, 801, 810, 819, 821, 827, 839, 840, 841, 843, 849, 854, 855, 877, 879, 894, 897, 939, 940, 943, 965, 970, 979, 985, 997, 1004, 1035, 1036, 1073, 1100, 1111, 1114, 1133, 1134, 1150, 1175, 1193, 1211, 1240, 1245)
City Load (20.3ms)  SELECT `cities`.* FROM `cities` WHERE `cities`.`id` IN (1100, 1217, 1661, 3201, 3206, 3215, 3320, 3380, 4100, 4215, 5201, 5210, 6201, 6202, 6204, 6205, 6210, 6380, 7201, 7203, 7300, 8440, 9201, 9203, 9204, 9205, 9209, 10202, 11100, 11201, 11203, 11206, 11208, 11214, 11219, 11222, 11224, 11225, 11232, 11460, 12100, 12203, 12204, 12206, 12207, 12208, 12211, 12212, 12213, 12215, 12216, 12217, 12219, 12220, 12221, 12222, 12232, 12320, 13101, 13102, 13103, 13104, 13106, 13107, 13108, 13109, 13111, 13112, 13113, 13116, 13121, 13122, 13201, 13202, 13204, 13206, 13207, 13208, 13209, 13214, 13222, 13227, 13300, 14100, 14130, 14150, 14201, 14206, 14212, 14215, 14216, 15206, 15222, 16201, 16205, 17201, 18201, 20201, 20202, 20203, 20205, 20206, 20207, 20208, 20210, 20212, 20215, 20218, 20220, 20320, 20360, 20420, 21201, 22100, 22130, 22203, 22206, 22207, 22209, 22210, 22211, 22212, 22213, 22214, 22215, 22216, 22220, 22221, 22225, 22226, 22340, 22420, 23100, 23202, 23204, 23206, 23207, 23211, 23212, 23219, 23230, 23360, 24201, 24203, 24207, 25201, 25206, 25210, 25213, 26100, 26201, 27100, 27140, 27210, 27219, 27221, 27227, 28100, 28201, 28202, 28204, 28210, 28216, 28217, 29201, 29203, 29420, 30201, 33100, 33202, 33205, 34100, 34207, 34300, 35201, 35216, 36201, 38201, 38202, 40130, 40300, 40620, 41201, 42202, 42203, 43100, 44201, 45201, 46201, 47201, 47210)

こんな感じにパースされずにそのまま出力されるようになります。

終わりに

ロジックで策が尽きた方はぜひお試しを！