rescueを使用すると実行時間が10倍近く長くなる

Question

###前提・実現したいこと
Rubyにおいてエラーが起きた際、プログラミングを止めない為にrescueを追加しました。
本来60秒程度で終わっていたプログラムが、640秒近くまで動作を終了するのに時間が掛かってしまいます。

考察ですが、rescueを使用する事によってタイムアウトするまで動作を繰り返しているのではないかと考えております。
使用している事コードは下記になります。

###該当のコード

	def point(i)
		if i.find_element(:xpath => ".//th[contains(text(),'ポイント利用')]").displayed? == true
			i.find_element(:xpath => ".//th[contains(text(),'ポイント利用')]/following-sibling::td").text()
		end
		rescue Selenium::WebDriver::Error::NoSuchElementError
			return "なし"
	end

###質問
rescueの使用法が間違っているのでしょうか？
また、もしタイムアウトをするまで動作を繰り返していた場合、タイムアウト時間を短くする方法または、繰り返させない方法を教えて頂けれないでしょうか
宜しくお願い致します。

###編集部分
ボトルネックになっている部分は条件分岐で使用しているelement_present?メソッドまたは、point_nextTDメソッドかと思います。
計測結果、element_present?にてrealが平均20秒掛かっています。
このrealの待機時間を解消する方法はないでしょうか？

###ベンチマークの実施結果
該当のコード

	def point(i)
				if element_present?(i, :xpath, ".//th[contains(text(),'ポイント利用（')]") == true
					point_nextTD(i)
				else
					return " "
				end
	end

	def element_present?(where, how, what)
		Benchmark.bm 10 do |r|
		r.report "条件分岐" do
			begin
				where.find_element(how => what)
				true
			rescue Selenium::WebDriver::Error::NoSuchElementError
				false
		end
		end
		end
	end

		def point_nextTD(i)
		Benchmark.bm 10 do |r|
			r.report "アクション" do
			i.find_element(:xpath => ".//th[contains(text(),'ポイント利用（')]/following-sibling::td").text().gsub(/[円]/,"").gsub(/[,]/,"").to_i
		end
		end
	end
		

ベンチマーク結果

                 user     system      total        real
条件分岐         0.040000   0.020000   0.060000 ( 26.678073)
                 user     system      total        real
条件分岐         0.050000   0.030000   0.080000 ( 25.499489)
                 user     system      total        real
条件分岐         0.010000   0.000000   0.010000 (  0.017920)
                 user     system      total        real
条件分岐         0.050000   0.030000   0.080000 ( 24.706779)
                 user     system      total        real
条件分岐         0.000000   0.000000   0.000000 (  0.011791)
                 user     system      total        real
条件分岐         0.000000   0.000000   0.000000 (  0.012549)
                 user     system      total        real
条件分岐         0.050000   0.020000   0.070000 ( 25.037440)
                 user     system      total        real
条件分岐         0.050000   0.020000   0.070000 ( 26.076752)
                 user     system      total        real
条件分岐         0.000000   0.000000   0.000000 (  0.018694)
                 user     system      total        real
アクション        0.000000   0.000000   0.000000 (  0.038412)
                 user     system      total        real
アクション        0.010000   0.000000   0.010000 (  0.028833)
                 user     system      total        real
アクション        0.010000   0.000000   0.010000 (  0.032794)
                 user     system      total        real
アクション        0.000000   0.000000   0.000000 (  0.026723)
                 user     system      total        real
アクション        0.000000   0.000000   0.000000 (  0.030527)

Answer 1

rescueの使用方法は誤りではありませんが、何かしらのループ内で例外処理を行うのは処理が遅くなる要因になります。

参考: rubyの例外処理が遅かった？はなし - Qiita

とは言えSelenium側で例外を投げるようにしているため、例外処理をしなければなりません。
Rubyバインディングのソースコードを斜め読みしてみましたが、恐らくこの辺りで書かれている通り、先にSelenium::WebDriver::Error::TimeOutErrorが発生して、メソッド内で該当エラーが投げられたらSelenium::WebDriver::Error::NoSuchElementErrorを投げ直すようにしているようです。

SeleniumのWikiに書いていないか見てみましたら、タイムアウトに関する項目がありました。
このページの説明によるとやはりfind_elementメソッドはNoSuchElementErrorを投げる前に指定時間待機するようなので、待機時間を明示することで対応するのが良さそうです。

全体のタイムアウトを設定するには以下のように行うようです。

driver = Selenium::WebDriver.for :firefox
driver.manage.timeouts.implicit_wait = 3 # seconds

一部（今回で言えばpointメソッドのみ）のタイムアウト時間を変えるには以下のようにするようです。

wait = Selenium::WebDriver::Wait.new(:timeout => 3)
wait.until { driver.find_element(:id => "cheese").displayed? }

Comments

[yuki_90453]

ご返事が遅くなってしまい申し訳ございません。
先程、私の環境で試してみましたが実行時間はあまり変わらず、あいかわらずとても時間が掛かってしまいます。
rescueを使わず、エラーで動作が止まらなくさせる方法はないのでしょうか？
def point(i)
if element_present?(i, :xpath, ".//table[@class='shipInfo']//th[contains(text(),'ポイント利用')]")
i.find_element(:xpath => ".//th[contains(text(),'ポイント利用')]/following-sibling::td").text()
else
return "なし"
end
end

def element_present?(where, how, what)
wait = Selenium::WebDriver::Wait.new(:timeout => 1)
# $selenium.manage.timeouts.implicit_wait = 0
wait.until{ where.find_element(how, what)}
true
# rescue Selenium::WebDriver::Error::NoSuchElementError
rescue Selenium::WebDriver::Error::TimeOutError
false
end

[yuki_90453]

このpointメソッドに引数は既にfind_elementで指定したセレクターが入ります。
ですのでpointメソッド内で使われているxpathはメソッドチェーンのような状態になっているのですが、それが原因で遅いのでしょうか？

[from_kyushu]

> メソッドチェーンのような状態になっているのですが、それが原因で遅いのでしょうか？

あまり関係がないと思われます。

こちらでベンチマークを取ってみたのですが、コメントではコードのハイライトが効かないようなので別回答として投稿します。

Answer 2

提示のコードだけではこちらで試せないので、以下のようなベンチマークを実行してみましたが実行時間は変わらないですね...。
10回程度実行してみましたが、全てに置いてSelenium::WebDriver::Waitを使ったほうが若干遅いという結果になりました。
systemとtotalの欄がWait非使用と比べてWait使用のほうが短いのは、恐らくfind_elementの実行結果がキャッシュされているためだと予想しています。

require "selenium-webdriver"
require "benchmark"

def accepting_label elem, timeout = 0
  wait = Selenium::WebDriver::Wait.new timeout: timeout
  wait.until{
    elem.find_element :xpath, "./div[@class='boxItemData']/p[@class='entry-stateLavel is-accepting']"
  }.text()
rescue Selenium::WebDriver::Error::TimeOutError
  "なし"
end

def accepting_label_notimeout elem
  elem.find_element(:xpath, "./div[@class='boxItemData']/p[@class='entry-stateLavel is-accepting']").text()
rescue Selenium::WebDriver::Error::NoSuchElementError
  "なし"
end

def label_notimeout elem
  elems = elem.find_elements(:xpath, "./div[@class='boxItemData']/p[@class='entry-stateLavel is-accepting']")
  elems.empty? ? "なし" : elems[0].text()
end

driver = Selenium::WebDriver.for :chrome
driver.get "https://teratail.com/tags/Ruby"

elements = driver.find_elements(:xpath, "//div[@class='boxContentWrap btnAttention']/ul/li")

Benchmark.bm(10) do |bm|
  bm.report "no timeout" do
    elements.each{|line| accepting_label_notimeout line}
  end

  bm.report "timeout = 0" do
    elements.each{|line| accepting_label line, 0}
  end

  bm.report "no rescue" do
    elements.each{|line| label_notimeout line}
  end
end

driver.quit

                 user     system      total        real
no timeout   0.000000   0.047000   0.047000 ( 28.840176)
timeout = 0  0.000000   0.015000   0.015000 ( 31.142968)
no rescue    0.000000   0.000000   0.000000 ( 28.656518)

こちらはteratailのRubyタグが付いた注目の質問からラベルが「受付中」になっているものを探すようにしてます。
「解決済」の場合はクラス名がis-resolvedのためTimeOutError(またはNoSuchElementError)が発生するようになっています。
ループ回数はそれぞれ20回程度です。
また、参考程度にfind_elementsメソッドが要素が見つからなければ空配列を返す仕様を利用してrescueを使用しないメソッドも作って実行してみましたが、ループ回数が20回程度であればrescueの有無は実行時間にさほど影響を与えないようです。

そもそも、質問者様の環境で起こっている速度低下の原因は本当に提示されたコードの部分なのでしょうか？
私は質問者様が提示されたコード以上の情報を知ることが出来ないため上記のようなベンチマークをでっち上げてみましたが、こちらで試した限りrescueの有無はさほど影響しないと判断せざるを得ないようです。
他にボトルネックになっている箇所（ページ読み込み速度がそもそも遅くなっている、前段階の処理に時間がかかっている等）がないか、一度切り分けを行ってみたほうがよいのではないかと思います。

Comments

[yuki_90453]

詳しいご回答ありがとうございます。
こちらもBenchmarkを使いボトルネックらしい部分でベンチマークを行って見ました。

結果、条件分岐の部分が時間掛かっているように思えます。(コード及び、結果は質問下部に追記しております。)
そのボトルネックの部分ですがuser,system,totalの部分は数値が低いのですが、realの部分だけ平均20秒近く掛かっております。
このreal部分は何か？調べてみたのですが、「CPU がぼーっとしていたり，他の仕事をやっている時間も含まれる。」と書かれておりましたが、なぜこの動作のみそのような状態になるのかわかりません。
このreal部分の何もしていない時間に問題があるのではないかと思いますが、どのように対処すればよいかご教授頂けないでしょうか。

[yuki_90453]

最後の部分について回答を忘れていました。
環境としては、他に何もアプリケーションを動作させていない状態で実施しております。
またボトルネックと思われる部分をコメントアウトし実行すると、600秒→50秒程になるので確実かと思います。

Answer 3

rescueって、

begin
 処理１
rescue 例外クラス
 rescueの処理
end 

だと思っていましたが（対象処理に範囲の限定の為？）
貴殿のソースにはbeginが見当たらない。
見当違いだったらすみません。

Comments

[maisumakun]

rescueはbeginだけではなく、メソッド定義のdefにぶら下げるような書き方もできます（classやmoduleにもかけられるらしいですが、使いみちはぱっと思いつきません）。

https://docs.ruby-lang.org/ja/latest/doc/spec=2fdef.html

[yuki_90453]

beginは必須なのでしょうか？動作に支障がないのであえて省略しております。

[退会済みユーザー]

begin があった方が見易い（理解し易い）ので、私は省略しないですね。