投稿者「三原健一」のアーカイブ

BIKE TOKYO 2015参加＆藤沢まで自走

BIKE TOKYO 2015

シルバーウィーク２日目の９月２０日 日曜日、BIKE TOKYO 2015というイベントに参加してきました。

イベントの詳細はリンクを見ていただければと思いますが、昨年まで「東京シティサイクリング」と呼んでいたのが、米ニューヨーク市の「BIKE NEW YORK」にならって改名したとのことです。

BIKE NEW YORKの参加者は約３万人。片やBIKE TOKYOは1,500人と規模は小さく、東京マラソンほどの知名度はありませんが、今年で１５回目とそれなりの実績はあるイベントのようです。

１ヶ月半くらい前に偶然このイベントのことを知り、直ぐにエントリーしました。（参加費は高校生以上6,000円）

コースは45.9km

コースは以下のように東京の中心の一番東京らしいポイントを結ぶ約46kmのコースです。
【スタート】有明（東京臨海広域防災公園） ～ 両国 〜 浅草 ～ 秋葉原 ～ 神保町 〜 飯田橋 〜 大久保 〜 新宿 ～ 初台 〜 代官山 〜 恵比寿 〜 六本木 ～ 霞ヶ関 〜 銀座 ～ 築地 ～ 【ゴール】有明（東京臨海広域防災公園）
※中間エイドステーション2ケ所（墨田区役所、都庁）

BIKETOKYO2015

東京は坂が多い街ですが、このコースは比較的高低差が少なくて初心者に優しいコースです。

実際、ロードバイクではなくいわゆるママチャリで参加している人も沢山いました。

スタートはグループ別に

1,500人も参加するということなので、事前に申告した時間帯別の５つのグループに分かれます。８時から１０時まで３０分間隔でAからEのグループ別、さらにグループの中での１０人ずつくらいに分かれてスタートします。

特にタイムを争う競技ではなく１６時までに帰って来ればどんなにゆっくり走っても良いという緩いルールしかありません。

スタートしてから10km過ぎくらいまでは、かなり団子状態になって走るので信号待ちでかなり停滞する感じです。

ニューヨークでのイベントはどうなのか興味がありますが、東京の場合はマラソンほど知名度もなく事前告知もほとんどないので、交通量の多い道路の左端を一列になって走るため、止まっている時間が長く感じます。

50kmもないので、３時間もあれば余裕でゴールできるだろうと計画を立てていたのですが、中間地点の都庁に着いたのがスタートしてからちょうど３時間後くらいでした。

それでも、コースの要所要所にはスタッフや警備員さんが立っていて誘導してくれるので安心して走ることができます。

いろんな街の表情が見える

この日はいろいろな街で秋祭りが行われていました。写真は東駒形付近で撮ったものです。

このように下町情緒満載なところもあれば代官山のようなお洒落な街を通ったり、自転車で空気を感じながら走るのはとても楽しいです。

東京に長年住んでいる人はもちろんですが、地方から来て東京をまだあまりよく知らない人が参加しても楽しめるイベントだと思います。

エイドステーション

途中２箇所のエイドステーションでは、水のペットボトルやバナナなどを配っています。

ちょうどトイレに行きたいと思っていたところだったので、助かりました。

気楽に参加した方が面白い

このようなイベントに参加するのは初めてだったのですが、いろいろ参考になりました。

1,500人も参加すると、ママチャリから高そうなロードバイクまでいろんな自転車が集まりますが、本格的なサイクリストはビンディング（固定式）・ペダルの人が多いように思いました。

ビンディング・ペダルはペダルを踏み込むだけでなく反対側に上げる時（引き足）も足がペダルに付いているので力を利用できます。信号が青に変わってダッシュした際も、（体力や機材自体が負けているのかもしれませんが）どんどんおいていかれます。

ただ、信号等で止まる度にペダルを外したり付けたりと、見ていて大変そうだなと思いました。別にタイムを競うようなイベントではないので、高いロードバイクを持っていない人は新たに買う必要はありません。

今回は一人で参加しましたが、家族や友人で参加して楽しく走った方が絶対に楽しめると思います。（並列して走るのは厳禁ですが。）

なるべく早い組でスタートして、途中おいしい店に寄って食事をするというのもいいかもしれません。

ゴールは５時間後

完走証

結局ゴールしたのは５時間後の１４時半でした。

予定では１２時から１２時半くらいには戻って来る予定にしていたのですが、困ったことになりました。

実は、来る時は妻に車で自転車を運んでもらったのですが、帰りはそのまま自宅のある藤沢まで乗って帰るというかなり無謀な計画を立てていたのです。

エイドステーションで食べた果物以外は何も食べていなかったので、とりあえずは売りに来ていたソーキ丼（８００円）を食べて帰路に備えることにしました。

ソーキ丼

腹が減っていたので一気に食べてしまいました。

藤沢に向けて出発

有明－藤沢

有明を１５時過ぎに出て藤沢に向かいました。

いつかは東京から自転車で帰りたいと思って今回計画したのですが、このままでは確実に日が暮れてしまうのでかなり憂鬱になりながらも出発しました。（予定ではぎりぎり日没までには帰るつもりでした。）

帰りは体力が落ちているのでなるべく坂が少ない道を計画しました。普段仕事をしている品川のビルを横目に見ながら走るのはちょっとワクワクします。

糖分が切れる前に鶴見あたりでいなり寿司と巻寿司を食べ水分補給をしました。

その後横浜に差し掛かったあたりで日没となり、買っておいたライトが役に立ちました。

暗いと安全面で不安を覚えますが、慌てず慎重に走ることに気を配りました。

戸塚まで来てホッとする

戸塚まで来ると走り慣れた道になってちょっと安心です。藤沢まで後少しです。

道路標識も藤沢までの距離を知らせてくれます。

東京から自宅まで走ってみたいと思ったのは、震災で職場から歩いて帰ることのシミュレーションをしたいと考えたからなのですが、万一歩いて帰るようなことになったら同じように道路標識を見て安堵感を覚えるのでしょうか。

19:30に帰宅

いろいろ紆余曲折がありましたが、何とか自宅マンションに19:30に帰ることができました。

朝9:30にイベントでスタートしてから１０時間後にやっと帰ってきました。

それにしても、イベント参加者でこんな距離を帰ったおバカな人は何人くらいいたのでしょうか？

夜は家族で焼肉

焼肉

激しい運動をして筋肉が傷んだ場合、良質のタンパク質を多く取って休養を十分取れば、「超回復」といって以前よりもっと筋肉が強化されるらしいです。

ということで、この日はシャワーを浴びてから家族でよく行く焼肉屋へ行きました。

三浦半島一周〜初の100km超え〜

金曜夜の楽しみ

ネットでサイクリング用のルートを作成するサイト「ルートラボ」を見つけてから、毎週金曜日の夜は週末のコースを作成するのが楽しみです。このサイトについてはいつか紹介するとして、先週箱根湯本まで往復約85kmを走ったので今度は初の100km超えを狙って三浦半島一周を企画してみました。

以前自宅のある藤沢から三浦半島の南端にある城ヶ島公園まで往復しましたが、今回は城ヶ島には渡らず三崎港から三浦半島をぐるっと回り、三浦海岸、久里浜、横須賀、逗子を通って鎌倉から藤沢に戻ってくるコースで、地図上の距離は104.1km。なかなかいい感じです。

朝6:25に出発

三浦半島一周

前回城ヶ島公園に行ったのは真夏だったので朝４時に起きて４時半過ぎにスタートしましたが、今回はだいぶ涼しくなってきたので6:25に出発しました。

藤沢駅から江ノ島へ出る道を一気に南下し、その後はひたすら海岸に沿って国道１３４号線をひた走ります。

葉山御用邸の前を通り陸上自衛隊武山駐屯地まではそれほど高低差がありませんが、京浜急行三崎口駅の少し先まで登りが続きます。このコースではこのあたりが最も標高が高くて約80mです。

最高点を過ぎると後は三崎港まで一気に下っていきます。

三崎港はかなりのどかだ

三崎港は入り江がいくつかあって、写真はその中の一つです。三浦半島の周りはこんな感じの道が多くてのんびり走るのはとても気持ちがよいです。

三浦半島南端は海抜30mくらいの台地になっていて、城ヶ島大橋の真下を直交する21%の急坂を通って台地の上まで一気に登ります。正直ここが一番しんどかったです。

台地の上には２基の風力発電用風車が回っていたり、スイカの収穫が終わってこれからダイコンの種まきをする畑が広がっていたり、のどかな風景が広がります。

台地の上にコンビニ（ヤマザキショップ フジトモ商店）があったのですが、急坂で体力を消耗したので（手作りっぽい）シュークリームとコーラで休憩です。（汗拭き用のタオルを忘れたのでタオルハンカチも買いました。）

東京湾側はかなり単調

三浦半島は先端の標高が高くなっているちょっと変わった半島ですが、三浦海岸から久里浜までは海岸沿いの単調な道が続きます。北寄りの風が強く吹いていたので、ちょうど向かい風となりそれも大変な一因だったのかもしれません。

今回はなるべく海岸に沿って周ろうと思ったので、久里浜から横須賀へ直行せずに、浦賀〜観音崎〜走水海岸（防衛大学校の下あたり）を通りました。ここまでで約70kmです。

走水から先横須賀市街までの馬堀海岸は道路がまっすぐで道も広く、外国の海岸のような趣です。横須賀というと海上自衛隊と米海軍の基地が海岸を占めているという意識がありましたが、馬堀海岸はかなり長く感じました。

三笠公園も横須賀軍港も今回はパス

せっかく横須賀に寄ったのだから艦を見ないととも思いましたが、初の100km超えという大きな目的があるので、今回はパスしました。京急田浦駅の手前を左折し、県道２４号線を逗子方面に向かって登っていきます。

最近読んだ本で、「80kmを過ぎると足に来る」という一節があったのですが、まさにその通りです。長い坂の頂上付近にあるコンビニに寄って冷たいジュースとかき氷で体温を下げました。

逗子から江ノ島まで一気に！

三浦半島の分水嶺を超えて西側に戻ってくるとだいぶ気が楽になります。

逗子駅付近はなかなか良さそうな店がいろいろあるようでかなり賑わっていました。逗子から鎌倉へ抜けると見慣れた道に出ました。

材木座海岸から稲村ガ崎〜江ノ島を通り、鵠沼海岸から北上して家に帰りました。

「Runtastic Road Bike PRO GPS サイクルコンピュータ」は未だに誤差があるようで、走行距離は108.57kmとなりましたが、事前に測ったコース長から考えても今回は間違いなく100km超えを達成できました。

確かに80kmと100kmとの間には大きな違いがあるように感じましたが、ロードバイクを始めて３ヶ月で何とか大台にたどり着けたのは自分にとっても大きな自信になりました。

 

箱根湯本駅まで往復

ケイデンス・センサーを付けてみた

最近、iPhoneが高機能サイクルコンピュータになるアプリ「Runtastic Road Bike PRO GPS サイクルコンピュータ」を使い始めましたが、iPhone単体だとGPS信号でのみ速度・走行距離の計測をするため、正確な値が得られていないような気がしたため「TOPEAK(トピーク) パノバイク ブルートゥース スマート スピード & ケイデンス センサー」というケイデンス（１分間あたりのクランクの回転数・単位はrpm）と車速がわかるセンサーを愛車に付けてみました。

テストを兼ねて箱根湯本駅まで往復

ケイデンスセンサーのテストを兼ねて、短い夏休みの最終日、自宅のある藤沢から箱根湯本駅まで往復（83km弱）してみました。

箱根湯本駅往復コース

小田原まで国道１号線をひた走る間は比較的平坦な道のりですが、小田原城を過ぎて箱根登山鉄道のガードをくぐったあたりから箱根湯本駅までずっと上り坂が続きます。（海抜約100m）

復路は途中まで往路と同じですが、大磯から国道１３４号線を海沿いに走るコースです。

涼しいと楽

今日は一応８月最終日ですが、猛暑だった頃が嘘のような涼しさです。昨日はずっと雨がふっていたので路面が若干濡れていてペイント上でスリップをしないように気をつけて走りましたが、涼しいとやはり走るのは楽です。

ただし、湿度は高目なので途中の給水はまめに行いました。

ケイデンス80rpm以上をキープ

今までは力まかせに重いギアでこいでいましたが、今日はせっかくケイデンス・センサーを付けたので、ケイデンス80rpm以上をキープするように注力してみました。

単調な道が続いてだんだんケイデンスが落ちてくると、これまでだったらギアを変えずにそのまま我慢していましたが、今日は躊躇なく１段軽くして80rpm以上をキープするようにしてみました。

ケイデンスが落ちてくるのは、上り坂なのか、向かい風なのか、それとも体力が落ちているからなのか、重いギアでガシガシ走っているとよくわからないのですが、80rpmを意識しているとそれがよくわかるような気がします。

ケイデンスをキープするということはタイヤから路面に伝わる力が変わらないということなので上り坂でもスピードがそれほど落ちません。

箱根湯本駅に到着

箱根湯本に到着

箱根湯本駅に至る道はだんだん急になって途中ギアを一番軽くする箇所もありましたが、ケイデンスに注意したおかげで初めてにしてはそれほど力を使い切る感もなく目的地に到着できました。

上の写真は坂を登りきって左端の箱根湯本駅までラストスパートしているところですが、左上のケイデンスは82rpmありますしスピードもそこそこ出ています。

箱根湯本駅

 

今日まで夏休みですが、箱根山の警戒レベルが上がっていることと、平日であること、それよりもまだ９時前なので人通りは少なかったです。

箱根山は遠い

箱根山

写真は昨日までの雨で普段より水量の多い早川ですが、この山を越えたところに芦ノ湖があります。箱根駅伝の５区を走る選手はここ箱根湯本から山道を一気に登っていきます。

私もいつかは箱根ヒルクライムに挑戦したいと思いますが、相当減量しないと。。。

スピードが速すぎる？

箱根湯本駅まで事前に測ったところ42km弱のはずだったのですが、Runtastic Road Bike PROが示す距離は49km弱とかなりの誤差があります。途中のスピードも「こんなに速くていいのかな？」というくらいの表示です。

実はケイデンス・センサーを取り付けた後にアプリ内でタイヤの外周をセットするようになっているのですが、その値を間違って多めに設定してしまったようです。感じとしては２割くらい速くなっているようです。

走行距離も速度を積算しているようなので、実際より多めに出てしまっています。

もう一度外周を正確に測り直して設定する必要がありそうです。

初の100km超え？

箱根湯本往復2015.08.31

 

帰りは国道１３４号線沿いに海を見ながら帰りました。アプリ上は走行距離104km以上と初の100km超えを達成したように見えますが、前述のように２割くらい多めに算出されていますので、リアルな100km超えはまた次の機会に挑戦します。

それでも、全走行時間のうちケイデンス80-94rpmの時間が45%、平均ケイデンスが78rpmだったので、初めてにしてはまずまずでした。

戦後７０年に亡き祖父を想う

両祖父はシベリア抑留経験者

私の祖父は２人ともすでに他界していますが、共に旧満州で７０年前に敗戦を迎えその後３年間シベリアに抑留されました。

極寒の地で強制労働に従事させられ、多くの同胞ははかなくも命を落としました。２人は必死に生き延び無事に帰国してそれぞれの家族と再会するのですが、それまでの３年間は熾烈を極めました。

２人は満州時代からお互いをよく知る仲でもあったのですが、やがてその子供同士が結ばれ生まれたのが私です。だから祖父たちに想いを馳せるとその運命に驚かずにはいられません。

抑留経験はあまりにも過酷だったのでしょう、私は直接じっくり話を聞いた覚えがないのですが、例えば「ノルマ」という言葉、これはロシア語で「強制的に与えられた仕事」の意味だそうでシベリア抑留者が持ち帰った言葉とも言われています。例えば「１日で丸太の伐採１０本」というノルマを達成できないと食事を抜かれたりという生活が毎日続きました。

ある時は、毒がはいっているとわかっているまんじゅうを出されたことがあったらしく、仲間の一人が空腹に耐えかね食べてしまい目の前で口から泡を吹いて死んでしまったこともあったそうです。

母方の祖父は今から３４年前に亡くなったのですが、旧制一高（現東京大学）で学んだくらい聡明であるだけでなく、亡くなる直前まで日記を書いていたような実直な人でした。シベリア抑留時代も必死に記録を続け、その一部をかろうじて持ち帰りました。

祖父が亡くなった後、祖父をよく知る方々が苦労してその記録を一冊の本にまとめました。

遺稿集「生き残る」

生き残る

これが祖父が残したかけがえのない記録をまとめた本ですが、自分だけでなく後世にも残すべき貴重な内容なので昨年くらいから少しずつ電子化しようとしています。

昭和２０年８月９日から始まる記録ですが、はしがきの部分だけこの場を借りて紹介したいと思います。

はしがき

満州国熱河省で役人生活をしていた私は承徳で終戦の日を迎えた。この地に在った西南防衛司令部は「命に依り……」と称していち早く司令官以下錦州市へ引き揚げながら、残留部隊とくに憲兵隊と在郷軍人会に命じて在留全邦人の徹底抗戦を強要した。女子供だけの疎開が八月十四日になって辛くも実現した。

入院中の一在郷軍人が、周囲のはからいで妻子と同じ引揚列車に乗り込もうとしたとき、駅警戒中の憲兵はうむを云わさず彼をひきずり降ろした。割当の済んだ客車の一つを、急に軍用車に変更になったからと乗客を下車させ、目の前で軍用貨物を積み込んだが、それは日本酒と麦酒の詰まった函の他将校家族の洗濯盥から下駄箱まで忘れない引越荷物だった。

聖徳放送局は憲兵隊におさえられ、十四日正午の玉音放送をはじめ終戦処理に関する報道は完全に禁止された。省公署の無電室でたまたま聴いていた数名の者も「この完全なデマ放送」を絶対に口外せぬことを誓約させられた。愚劣極まる混乱が十九日まで続いた。
省次長岸谷隆一郎氏は「徹底抗戦」のナンセンスと全邦人の急速疎開を主張した。進駐軍を待つためにはごく少数の幹部だけ残留すれば充分だとの彼の意見は、結局圧しつぶされた。一万三千の一般民団員はこの日へ兵営になっている承徳離宮に収容された。次長は最後の一人が行進の列に加わるのを見届けてから、自宅で夫人、二令嬢と毒を仰いで自決した。

我々は民団員なので、抑留されるなどとは夢にも考えず、ただ暴民から生命を護ってもらうために、離宮入りをしたのだと思っていた。しかし、我々の身柄を捕らえたソ連外蒙進駐軍の隊長は、一般民団員と兵隊との間に何の区別も見出してはくれなかたった。その理由についてはいろいろの説があった。進駐軍の側から事前交渉で「非戦団員は八月十六日までに奉天錦州の線まで後退させよ。爾後の残留者は戦闘員とみなす」との通牒をこちらの憲兵が握りつぶしたという説。六十万あった筈の関東軍を捕虜にしてみたら四十五万しかなかったので、不足分の穴埋めに地方人を捕らえたのだという説。

いずれにしても民団を兵隊から区別してもらう数限りない努力が払われ、離宮抑留中から輸送の途中、更にウランバートルに着いてからも、口頭といわず文書といわず、スターリン首相、モロトフ外相、チョイバルサン外蒙政府首席をはじめ収容所長、政治指導員に至までの執拗な嘆願と要求が続けられたのだが、結局すべては無駄だった。かくて遡北の地における地獄の三年間がわれらを迎えたのである。

輸送中の貨車の中から私の日記は始まったのだが、収容所生活も労働が次第に強化され、帰還の近づいた頃は文字通り睡眠時間もなくなり、寸刻を見つけては場所を選ばず尻を下し、仮眠をとるのにせいいっぱいだったので、とても鉛筆を握る余裕がなかった。日記の上で回顧できる生活は、その頃のうちでも、とにかく時間的にも或る程度のゆとりのあったことを示すものである。

紙に不自由しながら苦労してこしらえた小さなノートが三冊溜ったが、苦心して無事持ち帰れたのは内二冊だけだった。その中から抄録してみることにした。

昭和二十三年一月

なぜ今、７０年前の記録を見返す必要があるのか

このようなはしがきから始まる本ですが、なぜ罪もない民間人であった祖父がソ連の捕虜として捉えられ、シベリアの地で強制労働に従事させられなければならなかったのか？

平和な現代からは想像もできないような理不尽なことが７０年前に実際に行われていたという事実は決して風化させてはなりません。

このはしがきは何度でも読み返さなければならないと思います。

祖父の配偶者である祖母は９４歳の今も健在で、今日も私の家族と楽しく食事会をしましたが、そのような場でも祖母は必ず「戦争は二度としてはならない。」ということを何度も強調します。

近い将来、日本が戦争をする国になってしまったら、祖父母の世代に対して顔向けができません。

なぜ日本が無謀な戦争に突き進んでしまったのか、それを今真剣に考えるべき時だと思います。

オギノパンは自転車野郎御用達

神奈川県では有名なパン屋さん

神奈川県相模原市を本拠地とする「オギノパン」というパン屋さんがあります。
最近テレビでもよく紹介されていて、昔懐かしい「あげぱん」が人気の店です。

先日、横浜に買い物に行ったところ、デパートの一角の臨時店舗で名物のあんぱんを売っているのを偶然目にしたのですが、なぜかロードバイクが一緒に展示されていたので、そのことを店員さんに質問したところ、最近特にカロリーが必要なサイクリストにあげぱんが人気なのだそうです。

ということで、昨日の土曜日（８月８日）に家から片道２０キロもかからない厚木店にロードバイクで行ってみることにしました。

暑くなる前に出発

最近は猛暑日が続いているので、なるべく早く出発するようにしています。

先週は朝４時半に出発して三浦半島の先端にある城ヶ島公園に行ってきたのですが、往路は日もまだ低く快調でした。

ところが、城ヶ島公園で少しゆっくり休憩し過ぎたので、出発が７時半くらいになってしまい復路は日差しが強くなってほとんど熱中症になりかけながらやっとのことで８２キロの道のりを帰って来ました。

いつかは１００キロ超えを達成したいと思っているのですが、この猛暑の中では無謀な挑戦なので、今週末は５０キロ程度のコースを走ろうと考えていたところ、オギノパンのことを思い出したので行ってみることにしました。

結局出発は６時になってしまいましたが、なるべく最短コースを選んでオギノパン厚木店にまっしぐらです。

オギノパン往復

６時に出発したのは訳があって、実はこの厚木店は土日は７時に開店です。（平日は９時半開店）
あまり早く出発し過ぎても開店を待つことになってしまうので、７時半くらいに着くように出発しました。

オギノパン厚木店

オギノパンにはテラス席（向かって右）があって、焼きたてのパンをすぐに食べることができるようになってます。

バイクスタンド

ロードバイク用のバイクスタンドがあったりして、サイクリストにはうれしい店です。（この他にも店の外に清潔なトイレが完備されていたりもします。）

揚げパンとエッグカルボ

あげぱんを買おうとしたところ、「あと１分くらいお待ちいただければ、揚げたてのパンをお出しできますよ！」という店員さん。この辺の心遣いが憎いです！

その他、この店は少しボリュームのある調理パンがとても美味しそうで、右は「エッグカルボ」という中に卵が入ったなかなかの一品でした。

この２つでなんと３５８円なので、朝から得した気になりました。（あげぱんは１１０円です。）

この日は気温が高くなりそうだったので、急いで来た道を帰りました。（往復で約３９キロ）

まさかの２日連続

今日（８月９日）は、特に目的地を決めずにひたすら北に向かって走ったのですが、小田急線の相武台前駅まで来たところ、このまま町田方面に行くかどうかでなんとなくその気分にならずに座間から厚木方面に向かうことにしました。

先週や昨日と比べかなり涼しかったこともあり、ちょっと無理してみようという思いも背中を押しました。

相武台前からオギノパン

厚木まで来たら、今度は昨日行ったオギノパンにまた行きたくなったので急遽寄り道です。

アーモンドチョコデニッシュとミートソースピザ

今日はあげぱん以外に挑戦してみようと思い、アーモンドチョコデニッシュ（左）とミートソースピザ（右）です。これで４１０円！コストパフォーマンス高いです。

名物丹沢あんぱん

昨日手ぶらで帰ったところ、奥さんから「お土産は？」と責められたので、今日は名物のあんぱんをおみやげに買って帰りました。（ロードバイクは荷物を入れるところがないので、袋をハンドルに結びつけるという恥ずかしいやり方で持ち帰りました。）

ダイエット目的でも始めた自転車ですが、途中のグルメを楽しむという楽しみが病みつきになりそうです。

帰りは昨日と同じ道。今日は５２キロ、昨日と合わせて９０キロ超え。いい汗をかきました。

STATSPACKデータをExcelでグラフ化する②〜DBバッファ編1〜

今週の名言

「自分が多数派の側にいると気付いたら、もう意見を変えてもいい頃だ。」
マーク・トウェイン

最近、マーク・トウェインの名言が多いですが、偶然です。

DBバッファの統計を調査する。

前回は、stats$snapshot表からスナップショット一覧を取得するSQL文を紹介しました。
今回から、応用編としてこの表とパフォーマンス・データが格納された表を結合して、１日の統計情報の推移を見てみます。
最初は取っ付き易いDBバッファについて調べてみましょう。

DBバッファヒット率の計算式

DBバッファの目的は、頻繁にアクセスされるDBブロックをなるべくメモリ（DBバッファ）に保持しておくことで、低速なディスクI/Oを回避することです。DBバッファ・ヒット率とは、要求されたDBブロックがバッファ内に存在していた割合を示すもので、以下の計算式によります。

DBバッファヒット率
＝((CONSISTENT_GETS + DB_BLOCK_GETS)-(PHYSICAL_READS))➗(CONSISTENT_GETS + DB_BLOCK_GETS)✖️100

データ取得SQL文

DBバッファヒット率を取得する方法はいくつかありますが、ここではSTATS$BUFFER_POOL_STATISTICS表を使用する方法を紹介します。
この表はV$BUFFER_POOL_STATISTICSのスナップショットを保持しているものです。
また、DBバッファヒット率だけではなくBuffer Busy Wait統計情報も一緒に取得します。

今回のSTATSPACK環境は前回とは違って１時間ごとにスナップショットを取得している環境です。

select
os.INSTANCE_NUMBER
,to_char(trunc(os.SNAP_TIME,'mi'),'yyyy/mm/dd hh24:mi') sdate
--,os.SNAP_ID SNAP_ID1
--,ns.SNAP_ID SNAP_ID2
,nb.NAME buffer_pool_name
,decode(( (nb.CONSISTENT_GETS - ob.CONSISTENT_GETS)
         +(nb.DB_BLOCK_GETS   - nb.DB_BLOCK_GETS)),0,0,  -- 0除算回避
(trunc((((nb.CONSISTENT_GETS - ob.CONSISTENT_GETS)
         +(nb.DB_BLOCK_GETS   - nb.DB_BLOCK_GETS)
         )
         -(nb.PHYSICAL_READS  - ob.PHYSICAL_READS)
        )
        /((nb.CONSISTENT_GETS - ob.CONSISTENT_GETS)
         +(nb.DB_BLOCK_GETS   - nb.DB_BLOCK_GETS)
         )*100,1
       )
)
) bhr
,nb.BUFFER_BUSY_WAIT - ob.BUFFER_BUSY_WAIT bbw
from
STATS$SNAPSHOT os
,STATS$SNAPSHOT ns
,STATS$BUFFER_POOL_STATISTICS ob
,STATS$BUFFER_POOL_STATISTICS nb
where 1=1
and trunc(os.SNAP_TIME,'mi') between to_date('xxxx/xx/xx 00','yyyy/mm/dd hh24')
                                 and to_date('xxxx/xx/xx 23','yyyy/mm/dd hh24')
and trunc(ns.SNAP_TIME,'mi') = trunc(os.SNAP_TIME,'mi') + 1/24
and os.SNAP_ID               = ob.SNAP_ID
and os.DBID                  = ob.DBID
and os.INSTANCE_NUMBER       = ob.INSTANCE_NUMBER
and ns.SNAP_ID               = nb.SNAP_ID
and ns.DBID                  = nb.DBID
and os.INSTANCE_NUMBER       = ns.INSTANCE_NUMBER
and os.INSTANCE_NUMBER       = nb.INSTANCE_NUMBER
and os.INSTANCE_NUMBER       = 1
order by
os.instance_number
,to_char(os.SNAP_TIME,'yyyy/mm/dd hh24mi');

実行例

実行例は以下のようになります。

SQL> set pages 50
SQL> col BHR for 990.0
SQL> select
  2   os.INSTANCE_NUMBER
  3  ,to_char(trunc(os.SNAP_TIME,'mi'),'yyyy/mm/dd hh24:mi') sdate
  4  --,os.SNAP_ID SNAP_ID1
  5  --,ns.SNAP_ID SNAP_ID2
  6  ,nb.NAME buffer_pool_name
  7  ,decode(( (nb.CONSISTENT_GETS - ob.CONSISTENT_GETS)
  8           +(nb.DB_BLOCK_GETS   - nb.DB_BLOCK_GETS)),0,0,  -- 0除算回避
  9   (trunc((((nb.CONSISTENT_GETS - ob.CONSISTENT_GETS)
10           +(nb.DB_BLOCK_GETS   - nb.DB_BLOCK_GETS)
11           )
12           -(nb.PHYSICAL_READS  - ob.PHYSICAL_READS)
13          )
14          /((nb.CONSISTENT_GETS - ob.CONSISTENT_GETS)
15           +(nb.DB_BLOCK_GETS   - nb.DB_BLOCK_GETS)
16           )*100,1
17         )
18   )
19  ) bhr
20  ,nb.BUFFER_BUSY_WAIT - ob.BUFFER_BUSY_WAIT bbw
21  from
22   STATS$SNAPSHOT os
23  ,STATS$SNAPSHOT ns
24  ,STATS$BUFFER_POOL_STATISTICS ob
25  ,STATS$BUFFER_POOL_STATISTICS nb
26  where 1=1
27  and trunc(os.SNAP_TIME,'mi') between to_date('2015/07/28 00','yyyy/mm/dd hh24')
28                                   and to_date('2015/07/28 23','yyyy/mm/dd hh24')
29  and trunc(ns.SNAP_TIME,'mi') = trunc(os.SNAP_TIME,'mi') + 1/24
30  and os.SNAP_ID               = ob.SNAP_ID
31  and os.DBID                  = ob.DBID
32  and os.INSTANCE_NUMBER       = ob.INSTANCE_NUMBER
33  and ns.SNAP_ID               = nb.SNAP_ID
34  and ns.DBID                  = nb.DBID
35  and os.INSTANCE_NUMBER       = ns.INSTANCE_NUMBER
36  and os.INSTANCE_NUMBER       = nb.INSTANCE_NUMBER
37  and os.INSTANCE_NUMBER       = 1
38  order by
39   os.instance_number
40  ,to_char(os.SNAP_TIME,'yyyy/mm/dd hh24mi');

INSTANCE_NUMBER SDATE            BUFFER_POOL_NAME        BHR        BBW
--------------- ---------------- -------------------- ------ ----------
              1 2015/07/28 00:00 DEFAULT               100.0          0
              1 2015/07/28 01:00 DEFAULT               100.0          1
              1 2015/07/28 02:00 DEFAULT               100.0          0
              1 2015/07/28 03:00 DEFAULT               100.0          0
              1 2015/07/28 04:00 DEFAULT               100.0          0
              1 2015/07/28 05:00 DEFAULT               100.0          0
              1 2015/07/28 06:00 DEFAULT               100.0          1
              1 2015/07/28 07:00 DEFAULT               100.0          0
              1 2015/07/28 08:00 DEFAULT               100.0          0
              1 2015/07/28 09:00 DEFAULT               100.0          0
              1 2015/07/28 10:00 DEFAULT               100.0          0
              1 2015/07/28 11:00 DEFAULT               100.0          0
              1 2015/07/28 12:00 DEFAULT               100.0          0
              1 2015/07/28 13:00 DEFAULT               100.0          0
              1 2015/07/28 14:00 DEFAULT               100.0          1
              1 2015/07/28 15:00 DEFAULT               100.0          0
              1 2015/07/28 16:00 DEFAULT               100.0          2
              1 2015/07/28 17:00 DEFAULT                99.9          5
              1 2015/07/28 18:00 DEFAULT               100.0          0
              1 2015/07/28 19:00 DEFAULT               100.0          0
              1 2015/07/28 20:00 DEFAULT               100.0          0
              1 2015/07/28 21:00 DEFAULT               100.0          0
              1 2015/07/28 22:00 DEFAULT               100.0          0
              1 2015/07/28 23:00 DEFAULT               100.0          0

24行が選択されました。

この環境はアクティビティがほとんどないので、DBバッファヒット率はほぼ100%ですが、お手元のSTATSPACKではどのような結果が得られるでしょうか？
この結果を、MS Excelのシートにコピー＆ペーストしてグラフにしていくのですが、その要領は次回で紹介します。

テーブルの結合列について

STATS$SNAPSHOT表の主キーを構成する列を確認すると「SNAP_ID,DBID,INSTANCE_NUMBER」の３つの列から成っていることがわかります。

SQL> select TABLE_NAME,CONSTRAINT_NAME,COLUMN_NAME,POSITION
  2  from USER_CONS_COLUMNS
  3  where CONSTRAINT_NAME = 'STATS$SNAPSHOT_PK'
  4  order by POSITION;

TABLE_NAME      CONSTRAINT_NAME    COLUMN_NAME       POSITION
--------------- ------------------ --------------- ----------
STATS$SNAPSHOT  STATS$SNAPSHOT_PK  SNAP_ID                  1
STATS$SNAPSHOT  STATS$SNAPSHOT_PK  DBID                     2
STATS$SNAPSHOT  STATS$SNAPSHOT_PK  INSTANCE_NUMBER          3

一方、結合表であるSTATS$BUFFER_POOL_STATISTICS表の外部キーを確認すると、同様に「SNAP_ID,DBID,INSTANCE_NUMBER」となっていることがわかります。

SQL> select TABLE_NAME,CONSTRAINT_NAME,COLUMN_NAME,POSITION
  2  from USER_CONS_COLUMNS
  3  where CONSTRAINT_NAME = 'STATS$BUFFER_POOL_STATS_FK'
  4  order by POSITION;

TABLE_NAME                    CONSTRAINT_NAME              COLUMN_NAME       POSITION
----------------------------- ---------------------------- --------------- ----------
STATS$BUFFER_POOL_STATISTICS  STATS$BUFFER_POOL_STATS_FK   SNAP_ID                  1
STATS$BUFFER_POOL_STATISTICS  STATS$BUFFER_POOL_STATS_FK   DBID                     2
STATS$BUFFER_POOL_STATISTICS  STATS$BUFFER_POOL_STATS_FK   INSTANCE_NUMBER          3

STATSPACKデータのグラフ化は、基本的にSTATS$SNAPSHOT表と関連する表を結合してデータを取得しますが、結合列はこれら３つの列を必ず指定するようにしましょう。

続く

ツール・ド・フランスに想う

フルーム（英）が２度目の総合優勝！

世界最高峰の自転車レースであるツール・ド・フランスが今日（現地時間で７月２６日）最終日を迎え、イギリス人のクリストファー・フルームが２度目の総合優勝を果たしました。

【自転車レース】ツール・ド・フランス2015、閉幕。英国のフルームが2度目の総合優勝！

私は１ヶ月前にロードバイクを買ったばかりの超初心者ですが、NHK BS1で放送された「まいにち ツール・ド・フランス！」をそれこそ毎日録画して、毎週末ワクワクしながら観戦しました。

すべてが規格外！

ツール・ド・フランスという自転車レースがあることはよく知っていましたが、じっくり観るのは今年が初めてです。

テレビの解説や思わず買ってしまった「じこまん１」（玉井雪雄作）という自転車を題材にした漫画からのにわか知識ですが、初めて知ったツール・ド・フランスについて紹介したいと思います。

  • 期間は休息日２日を含む２３日間の２１ステージ
    • １日１ステージのレースが３週間ほぼ毎日続きます。長いコースは200kmを超えるものもあり、今年の総距離は3,400kmを超えるそうです。
  • コースは繋がっていない
    • フランス国内のみを走るのかと思ったのですが、今年のスタートはオランダのユトレヒトで、ベルギーを経由して北フランスに入りました。最初の休息日には飛行機で一気に南フランスへ飛びスペイン国境付近から次の日のレースを再開しました。
  • 平地では平均50〜60km/hのスピード、峠越えから降るときは100km/h超のスピード！
    • 私が下り坂でどんなに頑張っても、瞬間でさえ50km/hを超えることはまずないのですが、選手たちの脚力には本当にびっくりです。今年はダウンヒルで放牧中の牛の群れが道路を横切るというアクシデントがありましたが、衝突事故もなく切り抜けました。
  • 選手たちの１日の消費カロリーは８０００キロカロリーを超える
    • 自転車というスポーツは予想以上にカロリーを消費します。しかも、２０００メートル級の峠を一気に登ったりするので、選手は高カロリーの食事を摂らないと３週間闘えないとか。最初に肝臓を壊す選手が多いそうです。
  • 色つきのユニフォーム
    • 例えば、総合成績がトップの選手は黄色いジャージの「マイヨ・ジョーヌ」を着て走ります。その他ポイント賞や山岳賞などのいろいろな部門で１位の選手はそれぞれ決められた色のジャージを着ます。フランス語が得意な娘に聞いたところ、「マイヨ」は「服」で「ジョーヌ」は「黄色」という意味だそうです。昔の名選手の名前か何かと思ったのですが極めてそのものズバリの名前でした。
  • チームで戦うスポーツ
    • この辺がまだよくわからないのですが、一人で黙々と走るのではなく、チームでいろいろな戦術を考えて走る競技のようです。フルームは「スカイ」というチームのエースですが、彼が毎日「マイヨ・ジョーヌ」を守り最後までゴールできたのは、チームメンバーのアシストがあってこそでした。

見所いろいろ

山岳勝負 vs スプリント勝負

選手にもいろいろタイプがあって、２０００メートル級の山岳地帯に強い選手が活躍する山岳ステージの攻防も見ものですが、私は個人的にはゴール前のスプリント勝負にハマってしまいました。

私の一番のお気に入りは、ドイツのアンドレ・グライペル選手です。彼は最終日の第２１ステージでも最後に驚異的なスプリントを見せて見事優勝！今期４勝目を上げました。

彼の猛ダッシュは、脚にターボエンジンが付いているかのようです。スプリントのゴールシーンは日本のケイリンを彷彿させますが、200km近く走ってきた後ということを考えるとやはり恐るべきスタミナです。

観客の応援が熱い！

サッカー、モータースポーツそしてこのサイクルスポーツに関しては、日本人選手のレベルは着実に上がっていますが、観客の応援を含めた文化としての成熟度は１０年どころか５０年は遅れている気がします。

例えば、相撲文化がヨーロッパで日本を凌ぐようになることが想像できないように、日本のサイクルスポーツにおける観客の楽しみ方を含めた文化は、悔しいですが永遠に追いつけないのではないかと思います。

長い上り坂では、選手が通る両脇にびっしり人垣ができていて、ちょっと傾いただけで当たってしまうくらいです。そんな観客が旗を振ったり怒鳴るように選手を鼓舞したり、しまいには一緒に走って坂を登ったりとにかく熱いです。

世界に誇るSHIMANO

でも、日本の自転車部品メーカーSHIMANO（シマノ）は、一説によると世界のスポーツバイクの９割ものシェアを持っているとのことです。

SHIMANOが部品を供給しないと、ツール・ド・フランスも成り立たないことを考えると、日本人として非常に誇りを感じます！

ああ、来年のツールが待ち遠しい！！

STATSPACKデータをExcelでグラフ化する①

今週の名言

「成功の秘訣は、職業をレジャーとみなすことだ。」
マーク・トウェイン

STATSPACKについて書かれた名著

私の手元に１０年以上前に買った素晴らしい本があります。ORACLE9i ハイパフォーマンスチューニング―STATSPACK編という本で、実に１３年近く前に出版されすでに絶版となっていますが、古本市場ではまだ入手できるようです。

私はこの本を自炊（スキャナで読み込んでPDF化）しiPadに入れているのですが、今でも時々読み返すことがあります。

Oracleは今や12cとなっていますが、個人的にはOracleの基本的なアーキテクチャは8iくらいで出来上がり、9iは各種管理機能の自動化が進み始めたバージョンという認識です。

まだ、ASMは登場しておらずRACもあまり洗練されたものではありませんでしたが、インスタンス単体レベルの基本機能は9iでかなり完成されているので、9i時代に出版された本は今でも十分読むに価する内容です。また、8iや9i時代に出版されたOracle関連本は内容の濃さからより深いOracleを理解する上で非常に役に立ちます。

その中でもこの本にはSTATSPACKデータを活用することで、データベースの状態を把握するノウハウが満載です。

特に、インスタンスの情報をMS Excelでグラフ化することで傾向を分析し、問題が起きる前にプロアクティブな対応をする情報を得るテクニックはかなり有益です。

Oracle Enterprise Manager(OEM)でもAWRデータをグラフ表示させることは可能ですが、特にコスト上の理由からStandard Editionを使っている環境でAWRが使用できない場合でも、STATSPACKデータをExcelでグラフ化できれば、かなり高度な運用が可能になるかもしれません。

定期的にスナップショットを取って、２つのスナップショット間の差分データでレポートを作成するという仕組みはSTATSPACKもAWRも同じなので、実はグラフ化自体はAWRデータでも可能です。

しかし、このブログではORACLE9i ハイパフォーマンスチューニング―STATSPACK編で紹介されたSTATSPACKデータを活用するというコンセプトを継承しつつ、私が考案した独自スクリプトを紹介していきたいと思います。

ちなみに、この方法は以前実際に業務で使用したこともあります。

基本はスナップ番号のリスト

STATSPACKは、AWRのように最初から使えるようになっているものではないので、自分でインストールする必要がありますし、スナップショットを定期的に自動取得する設定も自分で行う必要があります。

この辺の要領は割愛しますが、STATSPACK がインストールされ３０分ごとにスナプッショトが取得されている環境を例に説明を始めます。

スナップショットが実行される度に、stats$snapshot表に１行レコードがインサートされます。

ある時間帯に実行されたスナップショットの番号（stats$snapshot.snap_id）と１つ前のスナップ番号の組み合わせが重要です。ある日付を指定し、スナップショット取得インターバルごとに２つのスナップショット番号を一覧化するSQLスクリプトが以下となります。

スナップ番号一覧取得スクリプト

select
 os.instance_number
,to_char(trunc(os.SNAP_TIME,'mi'),'yyyy/mm/dd hh24:mi') sdate
,os.SNAP_ID SNAP_ID1
,ns.SNAP_ID SNAP_ID2
from
 perfstat.stats$snapshot os
,perfstat.stats$snapshot ns
where 1=1
and trunc(os.SNAP_TIME,'mi') between to_date('xxxx/xx/xx 00','yyyy/mm/dd hh24') and to_date('xxxx/xx/xx+1 00','yyyy/mm/dd hh24') -- 日付で抽出
and trunc(ns.SNAP_TIME,'mi') = trunc(os.SNAP_TIME,'mi') + 1/48 -- インターバル分だけずらす
and os.instance_number = ns.instance_number
order by
 os.instance_number
,to_char(os.SNAP_TIME,'yyyy/mm/dd hh24mi');

実際は、１０行目の「xxxx/xx/xx」の部分に特定の日付を指定します。

１１行目の「1/48」は３０分のインターバルという意味で、多くの場合の１時間のインターバルであれば「1/24」となります。

もし、RAC環境でSTATSPACKを使っている場合は、「os.instance_number =1」などのインスタンス番号を指定する条件を追加してください。

実行例

06:59:43 SQL> run
  1  select
  2   os.instance_number
  3  ,to_char(trunc(os.SNAP_TIME,'mi'),'yyyy/mm/dd hh24:mi') sdate
  4  ,os.SNAP_ID SNAP_ID1
  5  ,ns.SNAP_ID SNAP_ID2
  6  from
  7   perfstat.stats$snapshot os
  8  ,perfstat.stats$snapshot ns
  9  where 1=1
 10  and trunc(os.SNAP_TIME,'mi') between to_date('2015/07/21 00','yyyy/mm/dd hh24') and to_date('2015/07/22 00','yyyy/mm/dd hh24') -- 日付で抽出
 11  and trunc(ns.SNAP_TIME,'mi') = trunc(os.SNAP_TIME,'mi') + 1/48 -- インターバル分だけずらす
 12  and os.instance_number = ns.instance_number
 13  order by
 14   os.instance_number
 15* ,to_char(os.SNAP_TIME,'yyyy/mm/dd hh24mi')

INSTANCE_NUMBER SDATE              SNAP_ID1   SNAP_ID2
--------------- ---------------- ---------- ----------
              1 2015/07/21 00:27         62         63
              1 2015/07/21 00:57         63         64
              1 2015/07/21 01:27         64         65
              1 2015/07/21 01:57         65         66
              1 2015/07/21 02:27         66         67
              1 2015/07/21 02:57         67         68
              1 2015/07/21 03:27         68         69
              1 2015/07/21 03:57         69         70
              1 2015/07/21 04:27         70         71
              1 2015/07/21 04:57         71         72
              1 2015/07/21 05:27         72         73

INSTANCE_NUMBER SDATE              SNAP_ID1   SNAP_ID2
--------------- ---------------- ---------- ----------
              1 2015/07/21 05:57         73         74
              1 2015/07/21 06:27         74         75
              1 2015/07/21 06:57         75         76
              1 2015/07/21 07:27         76         77
              1 2015/07/21 07:57         77         78
              1 2015/07/21 08:27         78         79
              1 2015/07/21 08:57         79         80
              1 2015/07/21 09:58         81         82
              1 2015/07/21 10:28         82         83
              1 2015/07/21 10:58         83         84
              1 2015/07/21 11:28         84         85

INSTANCE_NUMBER SDATE              SNAP_ID1   SNAP_ID2
--------------- ---------------- ---------- ----------
              1 2015/07/21 11:58         85         86
              1 2015/07/21 12:28         86         87
              1 2015/07/21 12:58         87         88
              1 2015/07/21 13:28         88         89
              1 2015/07/21 13:58         89         90
              1 2015/07/21 14:28         90         91
              1 2015/07/21 14:58         91         92
              1 2015/07/21 15:28         92         93
              1 2015/07/21 15:58         93         94
              1 2015/07/21 16:28         94         95
              1 2015/07/21 16:58         95         96

INSTANCE_NUMBER SDATE              SNAP_ID1   SNAP_ID2
--------------- ---------------- ---------- ----------
              1 2015/07/21 17:28         96         97
              1 2015/07/21 17:58         97         98
              1 2015/07/21 18:28         98         99
              1 2015/07/21 18:58         99        100
              1 2015/07/21 19:28        100        101
              1 2015/07/21 19:58        101        102
              1 2015/07/21 20:28        102        103
              1 2015/07/21 20:58        103        104
              1 2015/07/21 21:28        104        105
              1 2015/07/21 22:29        111        112
              1 2015/07/21 22:59        112        113

INSTANCE_NUMBER SDATE              SNAP_ID1   SNAP_ID2
--------------- ---------------- ---------- ----------
              1 2015/07/21 23:29        113        114
              1 2015/07/21 23:59        114        115

46行が選択されました。

手元の環境（ノートPC）で作ったサンプルなので１日２４時間で４８レコードとなるはずなのに２つ足りないのはご愛嬌ですが、３０分間隔で連続する２つのスナップ番号の組が得られていることがおわかりでしょうか？

次回以降で、この基本的な問い合わせをベースとして様々なパフォーマンス・データをグラフ化していきます。

続く

インスタンスのリスナーへの登録（その２）

今週の名言

「今日できることを明日にまで延ばすな｡」
フィリップ・ チェスターフィールド

前回のおさらい（Oracle 11gR2）

  1. リスナーにインスタンスがサービスとして登録されて初めて、インスタンス（データベース）に対するネット接続が可能となります。
  2. リスナーを後から起動すると、インスタンスが登録するまでにある程度の時間がかかります。（PMONが定期的にリスナーに登録しにいくので最長60秒程度かかる場合があります。）
  3. リスナーを先に起動しておくと、インスタンスは起動直後にリスナーに登録されます。
  4. 2.の場合でも「ALTER SYSTEM REGISTER」コマンドを実行すると、インスタンスを即時にリスナーへ登録することができます。

前回は、インスタンスのリスナーへの登録に関する挙動についてOracle11gR2で確認をしてみましたが、Oracle12cR1で同様の検証をしてみます。

サービス登録の動作を確認する（12cR1）

1. インスタンスを先に起動し、リスナーを後から起動する。

インスタンスを起動する

xx:xx:xx SQL> startup
ORACLEインスタンスが起動しました。

Total System Global Area  838860800 bytes
Fixed Size                  2929936 bytes
Variable Size             608176880 bytes
Database Buffers          222298112 bytes
Redo Buffers                5455872 bytes
データベースがマウントされました。
データベースがオープンされました。
14:37:15 SQL>

アラートログ

2015-07-05 14:37:15.408000 +09:00
Starting background process CJQ0
Completed: ALTER DATABASE OPEN
CJQ0 started with pid=31, OS id=3721

14:37:15 にインスタンス（データベース）が起動されました。

（正確には、インスタンスとはプロセス群とメモリから成るため、メモリ情報が表示された時がインスタンスの起動時刻となりますが、ここではインスタンス＝データベースの意味で使っていますので、データベースがオープンされた時刻をインスタンス起動と言っています。

このタイミングで tnsping と接続の確認を行ってみます。

[xx:xx:xx] $ tnsping ora12c

TNS Ping Utility for Linux: Version 12.1.0.2.0 - Production on 05-7月 -2015 14:38:16

Copyright (c) 1997, 2014, Oracle.  All rights reserved.

パラメータ・ファイルを使用しました:
/u01/app/oracle/product/12.1.0.2/db_1/network/admin/sqlnet.ora

エイリアスを解決するためにTNSNAMESアダプタを使用しました。
(DESCRIPTION = (ADDRESS = (PROTOCOL = TCP)(HOST = oraclelinux6.onefact.jp)(PORT = 1521)) (CONNECT_DATA = (SERVER = DEDICATED) (SERVICE_NAME = ora12c)))に接続の試行中
TNS-12541: TNS: リスナーがありません。
[14:38:16] $ 

[xx:xx:xx] $ sqlplus /nolog

SQL*Plus: Release 12.1.0.2.0 Production on 日 7月 5 14:39:24 2015

Copyright (c) 1982, 2014, Oracle.  All rights reserved.

xx:xx:xx SQL> conn scott/tiger@ora12c
ERROR:
ORA-12541: TNS: リスナーがありません

14:39:33 SQL>

リスナーが起動していないので、tnspingも接続も失敗します。
14:39:33 にネット接続を試みましたが、成功しませんでした。

リスナーを起動する

インスタンスの次にリスナーを起動します。

[xx:xx:xx] $ lsnrctl start

LSNRCTL for Linux: Version 12.1.0.2.0 - Production on 05-7月 -2015 14:40:54

Copyright (c) 1991, 2014, Oracle.  All rights reserved.

/u01/app/oracle/product/12.1.0.2/db_1/bin/tnslsnrを起動しています。お待ちください...

TNSLSNR for Linux: Version 12.1.0.2.0 - Production
システム・パラメータ・ファイルは/u01/app/oracle/product/12.1.0.2/db_1/network/admin/listener.oraです。
ログ・メッセージを/u01/app/oracle/diag/tnslsnr/oraclelinux6/listener/alert/log.xmlに書き込みました。
リスニングしています: (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=oraclelinux6.onefact.jp)(PORT=1521)))
リスニングしています: (DESCRIPTION=(ADDRESS=(PROTOCOL=ipc)(KEY=EXTPROC1521)))

(DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=oraclelinux6.onefact.jp)(PORT=1521)))に接続中
リスナーのステータス
------------------------
別名                      LISTENER
バージョン                TNSLSNR for Linux: Version 12.1.0.2.0 - Production
開始日                    05-7月 -2015 14:40:54
稼働時間                  0 日 0 時間 0 分 0 秒
トレース・レベル          off
セキュリティ              ON: Local OS Authentication
SNMP                      OFF
パラメータ・ファイル      /u01/app/oracle/product/12.1.0.2/db_1/network/admin/listener.ora
ログ・ファイル            /u01/app/oracle/diag/tnslsnr/oraclelinux6/listener/alert/log.xml
リスニング・エンドポイントのサマリー...
  (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=oraclelinux6.onefact.jp)(PORT=1521)))
  (DESCRIPTION=(ADDRESS=(PROTOCOL=ipc)(KEY=EXTPROC1521)))
リスナーはサービスをサポートしていません。
コマンドは正常に終了しました。
[14:40:54] $

14:40:54 にリスナーが起動しました。

リスナー起動直後に別コンソールからネット接続を試みます。

xx:xx:xx SQL> conn scott/tiger@ora12c
ERROR:
ORA-12514: TNS:
リスナーは接続記述子でリクエストされたサービスを現在認識していません

14:40:57 SQL> conn scott/tiger@ora12c
ERROR:
ORA-12514: TNS:
リスナーは接続記述子でリクエストされたサービスを現在認識していません

14:41:06 SQL> conn scott/tiger@ora12c
接続されました。
14:41:17 SQL>

14:40:57 と 14:41:06 にネット接続の試みは失敗し、14:41:17 に成功しました。
リスナー起動から23秒後に接続を確認できました。

リスナーログ

05-7月 -2015 14:40:57 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=ora12c)(CID=(PROGRAM=sqlplus)(HOST=oraclelinux6.onefact.jp)(USER=ora12c))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.11.18)(PORT=24694)) * establish * ora12c * 12514
TNS-12514: TNS: リスナーは現在、接続識別子でリクエストされているサービスを認識していません
2015-07-05 14:41:06.873000 +09:00
05-7月 -2015 14:41:06 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=ora12c)(CID=(PROGRAM=sqlplus)(HOST=oraclelinux6.onefact.jp)(USER=ora12c))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.11.18)(PORT=24713)) * establish * ora12c * 12514
TNS-12514: TNS: リスナーは現在、接続識別子でリクエストされているサービスを認識していません
2015-07-05 14:41:09.718000 +09:00
リスニングしています: (DESCRIPTION=(ADDRESS=(PROTOCOL=tcps)(HOST=oraclelinux6.onefact.jp)(PORT=5500))(Security=(my_wallet_directory=/u01/app/oracle/admin/ora12c/xdb_wallet))(Presentation=HTTP)(Session=RAW))
Dynamic address is already listened on (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=oraclelinux6.onefact.jp)(PORT=1521)))
05-7月 -2015 14:41:09 * service_register * ora12c * 0
2015-07-05 14:41:17.722000 +09:00
05-7月 -2015 14:41:17 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=ora12c)(CID=(PROGRAM=sqlplus)(HOST=oraclelinux6.onefact.jp)(USER=ora12c))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.11.18)(PORT=24735)) * establish * ora12c * 0
05-7月 -2015 14:41:18 * service_update * ora12c * 0

リスナーログから、正確には 14:41:09 に「service_register」確認できていますので、リスナー起動後 15秒でインスタンスが登録されたことがわかります。

2. リスナーを先に起動し、インスタンスを後から起動する

リスナーがすでに起動されている状態から、インスタンスを起動します。

xx:xx:xx SQL> startup
ORACLEインスタンスが起動しました。

Total System Global Area  838860800 bytes
Fixed Size                  2929936 bytes
Variable Size             608176880 bytes
Database Buffers          222298112 bytes
Redo Buffers                5455872 bytes
データベースがマウントされました。
データベースがオープンされました。
14:47:10 SQL>

14:47:10 にインスタンスが起動しました。

別コンソールから、インスタンス起動前と起動後にネット接続を試みます。

xx:xx:xx SQL> conn scott/tiger@ora12c
ERROR:
ORA-12514: TNS:
リスナーは接続記述子でリクエストされたサービスを現在認識していません

14:47:03 SQL> conn scott/tiger@ora12c
接続されました。
14:47:13 SQL>

14:47:03 に接続失敗していますが、14:47:13 には成功しています。

2015-07-05 14:46:19.450000 +09:00
05-7月 -2015 14:46:19 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=ora12c)(CID=(PROGRAM=sqlplus)(HOST=oraclelinux6.onefact.jp)(USER=ora12c))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.11.18)(PORT=24780)) * establish * ora12c * 12514
TNS-12514: TNS: リスナーは現在、接続識別子でリクエストされているサービスを認識していません
2015-07-05 14:47:03.841000 +09:00
05-7月 -2015 14:47:03 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=ora12c)(CID=(PROGRAM=sqlplus)(HOST=oraclelinux6.onefact.jp)(USER=ora12c))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.11.18)(PORT=24783)) * establish * ora12c * 12514
TNS-12514: TNS: リスナーは現在、接続識別子でリクエストされているサービスを認識していません
Dynamic address is already listened on (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=oraclelinux6.onefact.jp)(PORT=1521)))
05-7月 -2015 14:47:04 * service_register * ora12c * 0
2015-07-05 14:47:07.074000 +09:00
05-7月 -2015 14:47:07 * service_update * ora12c * 0
2015-07-05 14:47:08.779000 +09:00
05-7月 -2015 14:47:08 * service_update * ora12c * 0
2015-07-05 14:47:10.028000 +09:00
リスニングしています: (DESCRIPTION=(ADDRESS=(PROTOCOL=tcps)(HOST=oraclelinux6.onefact.jp)(PORT=5500))(Security=(my_wallet_directory=/u01/app/oracle/admin/ora12c/xdb_wallet))(Presentation=HTTP)(Session=RAW))
05-7月 -2015 14:47:10 * service_update * ora12c * 0
05-7月 -2015 14:47:10 * service_update * ora12c * 0
05-7月 -2015 14:47:10 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=ora12c)(CID=(PROGRAM=sqlplus)(HOST=oraclelinux6.onefact.jp)(USER=ora12c))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.11.18)(PORT=24787)) * establish * ora12c * 0
2015-07-05 14:47:13.033000 +09:00
05-7月 -2015 14:47:13 * service_update * ora12c * 0
2015-07-05 14:47:16.037000 +09:00
05-7月 -2015 14:47:16 * service_update * ora12c * 0
2015-07-05 14:47:46.056000 +09:00
05-7月 -2015 14:47:46 * service_update * ora12c * 0

3. インスタンスを先に起動し、リスナーを後から起動する。その後サービス登録コマンドを実行する。

インスタンスは起動済みですが、リスナーは起動されていない状態から始めます。

リスナーを起動する

[xx:xx:xx] $ lsnrctl start

LSNRCTL for Linux: Version 12.1.0.2.0 - Production on 05-7月 -2015 14:54:43

Copyright (c) 1991, 2014, Oracle.  All rights reserved.

/u01/app/oracle/product/12.1.0.2/db_1/bin/tnslsnrを起動しています。お待ちください...

TNSLSNR for Linux: Version 12.1.0.2.0 - Production
システム・パラメータ・ファイルは/u01/app/oracle/product/12.1.0.2/db_1/network/admin/listener.oraです。
ログ・メッセージを/u01/app/oracle/diag/tnslsnr/oraclelinux6/listener/alert/log.xmlに書き込みました。
リスニングしています: (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=oraclelinux6.onefact.jp)(PORT=1521)))
リスニングしています: (DESCRIPTION=(ADDRESS=(PROTOCOL=ipc)(KEY=EXTPROC1521)))

(DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=oraclelinux6.onefact.jp)(PORT=1521)))に接続中
リスナーのステータス
------------------------
別名                      LISTENER
バージョン                TNSLSNR for Linux: Version 12.1.0.2.0 - Production
開始日                    05-7月 -2015 14:54:43
稼働時間                  0 日 0 時間 0 分 0 秒
トレース・レベル          off
セキュリティ              ON: Local OS Authentication
SNMP                      OFF
パラメータ・ファイル      /u01/app/oracle/product/12.1.0.2/db_1/network/admin/listener.ora
ログ・ファイル            /u01/app/oracle/diag/tnslsnr/oraclelinux6/listener/alert/log.xml
リスニング・エンドポイントのサマリー...
  (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=oraclelinux6.onefact.jp)(PORT=1521)))
  (DESCRIPTION=(ADDRESS=(PROTOCOL=ipc)(KEY=EXTPROC1521)))
リスナーはサービスをサポートしていません。
コマンドは正常に終了しました。
[14:54:43] $

14:54:43 にリスナーが起動しました。

サービス登録コマンドを実行する

xx:xx:xx SQL> alter system register;
 システムが変更されました。
14:54:49 SQL>

14:54:49 にサービス登録コマンドを実行しました。

別コンソールから接続確認を行う。

確認を行った時間に注目してください。

xx:xx:xx SQL> conn scott/tiger@ora12c
ERROR:
ORA-12541: TNS: リスナーがありません

警告: Oracleにはもう接続されていません。
14:54:14 SQL> conn scott/tiger@ora12c
ERROR:
ORA-12514: TNS:
リスナーは接続記述子でリクエストされたサービスを現在認識していません

14:54:46 SQL> conn scott/tiger@ora12c
接続されました。
14:54:55 SQL>

14:54:14 は、まだリスナーが起動されていません。
14:54:46 は、リスナーが起動されていますが、インスタンスが登録されていません。
14:54:55 は、インスタンスが登録されたので接続に成功しています。

リスナーログ

05-7月 -2015 14:54:46 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=ora12c)(CID=(PROGRAM=sqlplus)(HOST=oraclelinux6.onefact.jp)(USER=ora12c))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.11.18)(PORT=24826)) * establish * ora12c * 12514
TNS-12514: TNS: リスナーは現在、接続識別子でリクエストされているサービスを認識していません
2015-07-05 14:54:49.477000 +09:00
リスニングしています: (DESCRIPTION=(ADDRESS=(PROTOCOL=tcps)(HOST=oraclelinux6.onefact.jp)(PORT=5500))(Security=(my_wallet_directory=/u01/app/oracle/admin/ora12c/xdb_wallet))(Presentation=HTTP)(Session=RAW))
05-7月 -2015 14:54:49 * service_register * ora12c * 0
2015-07-05 14:54:55.269000 +09:00
05-7月 -2015 14:54:55 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=ora12c)(CID=(PROGRAM=sqlplus)(HOST=oraclelinux6.onefact.jp)(USER=ora12c))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.11.18)(PORT=24846)) * establish * ora12c * 0
05-7月 -2015 14:54:55 * service_update * ora12c * 0
2015-07-05 14:55:34.498000 +09:00
05-7月 -2015 14:55:34 * service_update * ora12c * 0
2015-07-05 14:57:10.577000 +09:00
05-7月 -2015 14:57:10 * service_update * ora12c * 0

12cでも、状況を見る限りでは11gと同じ挙動が確認できました。

リスナー登録（LREG）プロセスについて深掘りする

サービス登録の挙動に関しては、11g と 12c で違いはありませんでしたが、12cから新しくできたLREGプロセスについてもっと深く調べてみます。

まずは、いきなりですがサービスが登録された状態からLREGプロセスをkillしてみます。

LREGをkillしてみる

[xx:xx:xx] $ ps -ef | grep lreg
ora12c    3982     1  0 14:47 ?        00:00:00 ora_lreg_ora12c
ora12c    4347  3108  0 15:01 pts/4    00:00:00 grep lreg
[xx:xx:xx] $ kill -9 3982
[15:01:22] $

15:01:22 にプロセスがkillされました。

アラートログ

2015-07-05 15:01:23.798000 +09:00
Instance Critical Process (pid: 19, ospid: 3982, LREG) died unexpectedly
PMON (ospid: 3946): terminating the instance due to error 500
System state dump requested by (instance=1, osid=3946 (PMON)), summary=[abnormal instance termination].
System State dumped to trace file /u01/app/oracle/diag/rdbms/ora12c/ora12c/trace/ora12c_diag_3960_20150705150123.trc
Dumping diagnostic data in directory=[cdmp_20150705150123], requested by (instance=1, osid=3946 (PMON)), summary=[abnormal instance termination].
Instance terminated by PMON, pid = 3946

LREGの異常終了を検知して、最終的にPMONがインスタンスをダウンさせています。

つまり、LREGは必須プロセスです。

リスナーログ

2015-07-05 15:00:55.732000 +09:00
05-7月 -2015 15:00:55 * service_update * ora12c * 0
2015-07-05 15:01:22.006000 +09:00
リスニングしていません: (DESCRIPTION=(ADDRESS=(PROTOCOL=tcps)(HOST=oraclelinux6.onefact.jp)(PORT=5500))(Security=(my_wallet_directory=/u01/app/oracle/admin/ora12c/xdb_wallet))(Presentation=HTTP)(Session=RAW))
05-7月 -2015 15:01:22 * service_died * ora12c * 12537

LREGが異常終了してインスタンスがダウンすると、リスナーには「service_died」のステータスが伝達され、インスタンスの登録が抹消されます。

まとめ

リスナーにインスタンスがサービスとして登録されるところを見てきましたが、HA構成で運用しているデータベースでは起動スクリプトにおいて、「データベース⇨リスナー」の順に起動している場合があるかもしれません。（私が１５年前にDBAをしていた時のスクリプトはそうでした。）

RACになって、特に11g移行はGrid Infrastructureの一部としてリスナーはデータベースの前に起動する仕組みになっていますが、まだまだHA構成のデータベースは世の中にあると思いますので、フェイルオーバー時にサービス登録が速やかに行われるよう「alter system register」コマンドが実行されるようになっているかを確認しても良いのではないでしょうか？

終わり

次回は、このプロセスの内部動作に迫ってみます。

続く

インスタンスのリスナーへの登録（その１）

今週の名言

「すべて商売は売りて喜び、買いて喜ぶようにすべし。売りて喜び、買いて喜ばざるは道にあらず。貸借の道もまた貸して喜び、借りて喜ばざるは道にあらず。」
二宮尊徳

今回もOracle Net関連

リスナーは重要

Oracleデータベースはよほどのことがない限り、クライアントからネットワーク経由で接続して使います。従って接続に伴う問題は非常に深刻です。

Oracleサポートの現場でも、接続障害の解決に求められる緊急度は特に高いようです。
Oracle Databaseで接続障害が発生した際の調査手法

最近のWebアプリケーションは、コネクションプールにより常時セッションを張っていることが多いので、リスナーは１日１回早朝等に再接続をするときだけ起動していればよいという考え方もあります。

しかし、データベースが正常に稼働していたとしても、リスナーが起動していなければ新たな接続すらできないので、リスナー・プロセスの起動とそれを監視することはやはり必要です。

インスタンスはリスナーに登録されなければならない

起動されたインスタンス（データベース）は、リスナーにサービスとして登録されていなければなりません。

$ lsnrctl status

LSNRCTL for Linux: Version 12.1.0.2.0 - Production on 05-7月 -2015 16:01:58

Copyright (c) 1991, 2014, Oracle.  All rights reserved.

(DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=oraclelinux6.onefact.jp)(PORT=1521)))に接続中
リスナーのステータス
------------------------
別名                      LISTENER
バージョン                TNSLSNR for Linux: Version 12.1.0.2.0 - Production
開始日                    05-7月 -2015 14:54:43
稼働時間                  0 日 1 時間 7 分 15 秒
トレース・レベル          off
セキュリティ              ON: Local OS Authentication
SNMP                      OFF
パラメータ・ファイル      /u01/app/oracle/product/12.1.0.2/db_1/network/admin/listener.ora
ログ・ファイル            /u01/app/oracle/diag/tnslsnr/oraclelinux6/listener/alert/log.xml
リスニング・エンドポイントのサマリー...
  (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=oraclelinux6.onefact.jp)(PORT=1521)))
  (DESCRIPTION=(ADDRESS=(PROTOCOL=ipc)(KEY=EXTPROC1521)))
  (DESCRIPTION=(ADDRESS=(PROTOCOL=tcps)(HOST=oraclelinux6.onefact.jp)(PORT=5500))(Security=(my_wallet_directory=/u01/app/oracle/admin/ora12c/xdb_wallet))(Presentation=HTTP)(Session=RAW))
サービスのサマリー...
サービス"ora12c"には、1件のインスタンスがあります。
  インスタンス"ora12c"、状態READYには、このサービスに対する1件のハンドラがあります...
サービス"ora12cXDB"には、1件のインスタンスがあります。
  インスタンス"ora12c"、状態READYには、このサービスに対する1件のハンドラがあります...
コマンドは正常に終了しました。

Oracle 12cからサービス登録が変わった？

マニュアルを見ていて、11gと12cの微妙な違いに気がつきました。

Oracle® Database Net Services管理者ガイド
11gリリース2 (11.2)
B56288-04

サービス登録

PMONプロセスがリスナーに自動的に情報を登録する機能。

Oracle® Database Net Services管理者ガイド
12cリリース1 (12.1)
B71288-03

サービス登録

リスナー登録(LREG)プロセスがリスナーに自動的に情報を登録する機能です。

12cになって、従来のPMONに代わって新規に実装されたLREGというプロセスがサービス（リスナー）登録を行うようになったようですが、サービス登録の内部動作が変わったりしたのでしょうか？
気になったので確認してみることにします。

サービス登録の動作を確認する

11gR2

1. インスタンスを先に起動し、リスナーを後から起動する。

インスタンスとリスナーのどちらを先に起動させるかで、挙動が異なるかを確認します。
最初にデータベースを起動します。

データベースを起動する。

xx:xx:xx SQL> startup
ORACLEインスタンスが起動しました。

Total System Global Area  835104768 bytes
Fixed Size		    2257840 bytes
Variable Size		  536874064 bytes
Database Buffers	  289406976 bytes
Redo Buffers		    6565888 bytes
データベースがマウントされました。
データベースがオープンされました。
13:45:46 SQL>

アラートログ

2015-07-05 13:45:46.982000 +09:00
Completed: ALTER DATABASE OPEN
db_recovery_file_dest_size of 4182 MB is 0.00% used. This is a
user-specified limit on the amount of space that will be used by this
database for recovery-related files, and does not reflect the amount of
space available in the underlying filesystem or ASM diskgroup.
Starting background process CJQ0
CJQ0 started with pid=21, OS id=4628

13:45:46 にインスタンスが起動しました。

このタイミングで、tnspingと接続の確認を行ってみます。

[xx:xx:xx] $ sqlplus /nolog

SQL*Plus: Release 11.2.0.4.0 Production on 日 7月 5 13:47:49 2015

Copyright (c) 1982, 2013, Oracle.  All rights reserved.

13:47:49 SQL> conn scott/tiger@orcl
ERROR:
ORA-12541: TNS: リスナーがありません

リスナーが起動していないので、tnspingも接続も失敗することがわかります。

リスナーを起動する。

インスタンスの次にリスナーを起動します。

[xx:xx:xx] $ lsnrctl start

LSNRCTL for Linux: Version 11.2.0.4.0 - Production on 05-7月 -2015 13:48:51
............................................................................

リスナー起動直後に別コンソールからネット接続を試みます。

xx:xx:xx SQL> conn scott/tiger@orcl
ERROR:
ORA-12514: TNS:
リスナーは接続記述子でリクエストされたサービスを現在認識していません

13:48:53 SQL> conn scott/tiger@orcl
ERROR:
ORA-12514: TNS:
リスナーは接続記述子でリクエストされたサービスを現在認識していません

13:49:10 SQL>

13:48:53 と 13:49:10 にネット接続を試みましたが、成功しませんでした。

リスナーログ

05-7月 -2015 13:48:51 * (CONNECT_DATA=(CID=(PROGRAM=)(HOST=oraclelinux.onefact.jp)(USER=oracle))(COMMAND=status)(ARGUMENTS=64)(SERVICE=LISTENER)(VERSION=186647552)) * status * 0
2015-07-05 13:48:53.488000 +09:00
05-7月 -2015 13:48:53 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=orcl.onefact.jp)(CID=(PROGRAM=sqlplus)(HOST=oraclelinux.onefact.jp)(USER=oracle))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.11.15)(PORT=60167)) * establish * orcl.onefact.jp * 12514
TNS-12514: TNS: リスナーは現在、接続識別子でリクエストされているサービスを認識していません
2015-07-05 13:49:10.279000 +09:00
05-7月 -2015 13:49:10 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=orcl.onefact.jp)(CID=(PROGRAM=sqlplus)(HOST=oraclelinux.onefact.jp)(USER=oracle))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.11.15)(PORT=60185)) * establish * orcl.onefact.jp * 12514
TNS-12514: TNS: リスナーは現在、接続識別子でリクエストされているサービスを認識していません

13:48:51 にリスナーを起動しましたが、ネット接続を試みた時点でリスナーがサービスを認識していないことはリスナーログからも確認することができます。

それでも、接続を試みます。

xx:xx:xx SQL> conn scott/tiger@orcl
接続されました。
13:49:46 SQL>

13:49:46 にやっとネット接続が成功しました。

リスナーログ抜粋

2015-07-05 13:49:43.579000 +09:00
Dynamic address is already listened on (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=oraclelinux.onefact.jp)(PORT=1521)))
05-7月 -2015 13:49:43 * service_register * orcl * 0
2015-07-05 13:49:46.453000 +09:00
05-7月 -2015 13:49:46 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=orcl.onefact.jp)(CID=(PROGRAM=sqlplus)(HOST=oraclelinux.onefact.jp)(USER=oracle))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.11.15)(PORT=60205)) * establish * orcl.onefact.jp * 0
05-7月 -2015 13:49:46 * service_update * orcl * 0
2015-07-05 13:50:28.619000 +09:00

リスナーログを見ると、13:49:43 に「service_register」というのが確認できます。
これがリスナーがインスタンスをサービスとして認識したことを表し、以降ネット接続が可能となります。

リスナーを起動してからサービスが登録されるまで、52秒もかかっています。

2. リスナーを先に起動し、インスタンスを後から起動する。

時間の前後が逆になってしまっていますが、今度はリスナーを先に起動するパターンを確認します。

リスナー起動前の状態

[13:37:19] $ tnsping orcl

TNS Ping Utility for Linux: Version 11.2.0.4.0 - Production on 05-7月 -2015 13:37:45

Copyright (c) 1997, 2013, Oracle.  All rights reserved.

パラメータ・ファイルを使用しました:
/u01/app/oracle/product/11.2.0.4/db_1/network/admin/sqlnet.ora

エイリアスを解決するためにTNSNAMESアダプタを使用しました。
(DESCRIPTION = (ADDRESS = (PROTOCOL = TCP)(HOST = oraclelinux.onefact.jp)(PORT = 1521)) (CONNECT_DATA = (SERVER = DEDICATED) (SERVICE_NAME = orcl.onefact.jp)))に接続の試行中
TNS-12541: TNS: リスナーがありません。

リスナーを起動する。

[13:36:38] $ lsnrctl start

LSNRCTL for Linux: Version 11.2.0.4.0 - Production on 05-7月 -2015 13:38:18

Copyright (c) 1991, 2013, Oracle.  All rights reserved.

/u01/app/oracle/product/11.2.0.4/db_1/bin/tnslsnrを起動しています。お待ちください...

TNSLSNR for Linux: Version 11.2.0.4.0 - Production
システム・パラメータ・ファイルは/u01/app/oracle/product/11.2.0.4/db_1/network/admin/listener.oraです。
ログ・メッセージを/u01/app/oracle/diag/tnslsnr/oraclelinux/listener/alert/log.xmlに書き込みました。
リスニングしています: (DESCRIPTION=(ADDRESS=(PROTOCOL=ipc)(KEY=EXTPROC1521)))
リスニングしています: (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=oraclelinux.onefact.jp)(PORT=1521)))

(DESCRIPTION=(ADDRESS=(PROTOCOL=IPC)(KEY=EXTPROC1521)))に接続中
リスナーのステータス
------------------------
別名                      LISTENER
バージョン                TNSLSNR for Linux: Version 11.2.0.4.0 - Production
開始日                    05-7月 -2015 13:38:18
稼働時間                  0 日 0 時間 0 分 0 秒
トレース・レベル          off
セキュリティ              ON: Local OS Authentication
SNMP                      OFF
パラメータ・ファイル      /u01/app/oracle/product/11.2.0.4/db_1/network/admin/listener.ora
ログ・ファイル            /u01/app/oracle/diag/tnslsnr/oraclelinux/listener/alert/log.xml
リスニング・エンドポイントのサマリー...
  (DESCRIPTION=(ADDRESS=(PROTOCOL=ipc)(KEY=EXTPROC1521)))
  (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=oraclelinux.onefact.jp)(PORT=1521)))
リスナーはサービスをサポートしていません。
コマンドは正常に終了しました。
[13:38:18] $

13:38:18 にリスナーを起動しましたが、インスタンスはまだ起動されていないので、当然サービスとして登録されていません。

リスナーログ抜粋

2015-07-05 13:38:18.674000 +09:00
システム・パラメータ・ファイルは/u01/app/oracle/product/11.2.0.4/db_1/network/admin/listener.oraです。
ログ・メッセージを/u01/app/oracle/diag/tnslsnr/oraclelinux/listener/alert/log.xmlに書き込みました。
トレース情報を/u01/app/oracle/diag/tnslsnr/oraclelinux/listener/trace/ora_4467_140172889650944.trcに書き込みました。
トレース・レベルは現在0です。

pid=4467で起動しました
リスニングしています: (DESCRIPTION=(ADDRESS=(PROTOCOL=ipc)(KEY=EXTPROC1521)))
リスニングしています: (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=oraclelinux.onefact.jp)(PORT=1521)))
Listener completed notification to CRS on start

TIMESTAMP * CONNECT DATA [* PROTOCOL INFO] * EVENT [* SID] * RETURN CODE
WARNING: Subscription for node down event still pending
05-7月 -2015 13:38:18 * (CONNECT_DATA=(CID=(PROGRAM=)(HOST=oraclelinux.onefact.jp)(USER=oracle))(COMMAND=status)(ARGUMENTS=64)(SERVICE=LISTENER)(VERSION=186647552)) * status * 0

ここでtnspingを試してみます。

[13:37:45] $ tnsping orcl

TNS Ping Utility for Linux: Version 11.2.0.4.0 - Production on 05-7月 -2015 13:39:17

Copyright (c) 1997, 2013, Oracle.  All rights reserved.

パラメータ・ファイルを使用しました:
/u01/app/oracle/product/11.2.0.4/db_1/network/admin/sqlnet.ora

エイリアスを解決するためにTNSNAMESアダプタを使用しました。
(DESCRIPTION = (ADDRESS = (PROTOCOL = TCP)(HOST = oraclelinux.onefact.jp)(PORT = 1521)) (CONNECT_DATA = (SERVER = DEDICATED) (SERVICE_NAME = orcl.onefact.jp)))に接続の試行中
OK (0ミリ秒)
[13:39:17] $

リスナーが起動済みなので、tnspingは成功します。
つまり、tnspingはインスタンスへの接続を確認するものではなく、リスナーが機能しているかを確認する目的で使うものです。

リスナーログ抜粋

2015-07-05 13:39:17.149000 +09:00
05-7月 -2015 13:39:17 * ping * 0

インスタンスを起動する

リスナーが起動されているのを確認できたので、次にインスタンスを起動します。

13:36:03 SQL> startup
ORACLEインスタンスが起動しました。

Total System Global Area  835104768 bytes
Fixed Size		    2257840 bytes
Variable Size		  536874064 bytes
Database Buffers	  289406976 bytes
Redo Buffers		    6565888 bytes
データベースがマウントされました。
データベースがオープンされました。
13:41:36 SQL>

13:41:36 にインスタンスが起動されました。

アラートログ抜粋

2015-07-05 13:41:36.771000 +09:00
Completed: ALTER DATABASE OPEN
db_recovery_file_dest_size of 4182 MB is 0.00% used. This is a
user-specified limit on the amount of space that will be used by this
database for recovery-related files, and does not reflect the amount of
space available in the underlying filesystem or ASM diskgroup.
Starting background process CJQ0
CJQ0 started with pid=22, OS id=4541

別コンソールからネット接続を試みます。

[xx:xx:xx] $ sqlplus /nolog

SQL*Plus: Release 11.2.0.4.0 Production on 日 7月 5 13:41:09 2015

Copyright (c) 1982, 2013, Oracle.  All rights reserved.

13:41:09 SQL> conn scott/tiger@orcl
ERROR:
ORA-12528: TNS:リスナー:
該当するインスタンスはすべて、新規接続をブロックしています

13:41:31 SQL> conn scott/tiger@orcl
接続されました。
13:41:40 SQL>

startupコマンド投入直後である、13:41:09 においてリスナーは起動済みですが、まだインスタンスは新規接続を受け付けない状態です。（ORA-12528）
ただし、インスタンス起動完了直後の 13:41:40 には接続が成功していることがわかります。

リスナーを後から起動した場合と比べて明らかに早いです。

2015-07-05 13:41:29.890000 +09:00
Dynamic address is already listened on (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=oraclelinux.onefact.jp)(PORT=1521)))
05-7月 -2015 13:41:29 * service_register * orcl * 0
2015-07-05 13:41:31.303000 +09:00
2015-07-05 13:41:31.303000 +09:00
05-7月 -2015 13:41:31 * service_update * orcl * 0
05-7月 -2015 13:41:31 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=orcl.onefact.jp)(CID=(PROGRAM=sqlplus)(HOST=oraclelinux.onefact.jp)(USER=oracle))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.11.15)(PORT=60132)) * establish * orcl.onefact.jp * 12528
TNS-12528: TNS:リスナー: 該当するインスタンスはすべて、新規接続をブロックしています
2015-07-05 13:41:35.882000 +09:00
05-7月 -2015 13:41:35 * service_update * orcl * 0
2015-07-05 13:41:37.360000 +09:00
05-7月 -2015 13:41:37 * service_update * orcl * 0
2015-07-05 13:41:40.363000 +09:00
05-7月 -2015 13:41:40 * service_update * orcl * 0
05-7月 -2015 13:41:40 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=orcl.onefact.jp)(CID=(PROGRAM=sqlplus)(HOST=oraclelinux.onefact.jp)(USER=oracle))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.11.15)(PORT=60135)) * establish * orcl.onefact.jp * 0

3. インスタンスを先に起動し、リスナーを後から起動する。その後サービス登録コマンドを実行する。

インスタンスは起動済みですが、リスナーは起動されていない状態から始めます。
念のため、ネット接続を試みてみます。

xx:xx:xx SQL> conn scott/tiger@orcl
ERROR:
ORA-12541: TNS: リスナーがありません

13:59:47 SQL>

リスナーを起動する。

[xx:xx:xx] $ lsnrctl start

LSNRCTL for Linux: Version 11.2.0.4.0 - Production on 05-7月 -2015 14:00:17

Copyright (c) 1991, 2013, Oracle.  All rights reserved.

/u01/app/oracle/product/11.2.0.4/db_1/bin/tnslsnrを起動しています。お待ちください...

TNSLSNR for Linux: Version 11.2.0.4.0 - Production
システム・パラメータ・ファイルは/u01/app/oracle/product/11.2.0.4/db_1/network/admin/listener.oraです。
ログ・メッセージを/u01/app/oracle/diag/tnslsnr/oraclelinux/listener/alert/log.xmlに書き込みました。
リスニングしています: (DESCRIPTION=(ADDRESS=(PROTOCOL=ipc)(KEY=EXTPROC1521)))
リスニングしています: (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=oraclelinux.onefact.jp)(PORT=1521)))

(DESCRIPTION=(ADDRESS=(PROTOCOL=IPC)(KEY=EXTPROC1521)))に接続中
リスナーのステータス
------------------------
別名                      LISTENER
バージョン                TNSLSNR for Linux: Version 11.2.0.4.0 - Production
開始日                    05-7月 -2015 14:00:17
稼働時間                  0 日 0 時間 0 分 0 秒
トレース・レベル          off
セキュリティ              ON: Local OS Authentication
SNMP                      OFF
パラメータ・ファイル      /u01/app/oracle/product/11.2.0.4/db_1/network/admin/listener.ora
ログ・ファイル            /u01/app/oracle/diag/tnslsnr/oraclelinux/listener/alert/log.xml
リスニング・エンドポイントのサマリー...
  (DESCRIPTION=(ADDRESS=(PROTOCOL=ipc)(KEY=EXTPROC1521)))
  (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=oraclelinux.onefact.jp)(PORT=1521)))
リスナーはサービスをサポートしていません。
コマンドは正常に終了しました。
[14:00:17] $

リスナー起動直後に接続確認をする。

xx:xx:xx SQL> conn scott/tiger@orcl
ERROR:
ORA-12514: TNS:
リスナーは接続記述子でリクエストされたサービスを現在認識していません

14:00:19 SQL>

リスナーログ抜粋

05-7月 -2015 14:00:17 * (CONNECT_DATA=(CID=(PROGRAM=)(HOST=oraclelinux.onefact.jp)(USER=oracle))(COMMAND=status)(ARGUMENTS=64)(SERVICE=LISTENER)(VERSION=186647552)) * status * 0
2015-07-05 14:00:19.326000 +09:00
05-7月 -2015 14:00:19 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=orcl.onefact.jp)(CID=(PROGRAM=sqlplus)(HOST=oraclelinux.onefact.jp)(USER=oracle))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.11.15)(PORT=60262)) * establish * orcl.onefact.jp * 12514
TNS-12514: TNS: リスナーは現在、接続識別子でリクエストされているサービスを認識していません

14:00:17 にリスナーを起動しましたが、起動直後はまだインスタンスを認識していないため接続は ORA(TNS)-12514 エラーで失敗します。

インスタンスを明示的にリスナーに登録する。

xx:xx:xx SQL> alter system register;

システムが変更されました。

13:59:31 SQL> alter system register;

システムが変更されました。

14:00:25 SQL>

14:00:25 に投入した「ALTER SYSTEM REGISTER」コマンドにより、1.のように52秒も待たずにインスタンスをリスナーへ登録することができます。
実は、リスナー起動前の 13:59:31 にもこのコマンドを実行していますが、インスタンス登録先のリスナーがないにもかかわらず特にエラーにならずに終了しています。

2015-07-05 14:00:25.437000 +09:00
05-7月 -2015 14:00:25 * service_register * orcl * 0
2015-07-05 14:00:33.233000 +09:00
05-7月 -2015 14:00:33 * (CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=orcl.onefact.jp)(CID=(PROGRAM=sqlplus)(HOST=oraclelinux.onefact.jp)(USER=oracle))) * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.11.15)(PORT=60278)) * establish * orcl.onefact.jp * 0
2015-07-05 14:00:34.445000 +09:00
05-7月 -2015 14:00:34 * service_update * orcl * 0

conn scott/tiger@orcl
接続されました。
14:00:33 SQL>

インスタンスがリスナーに登録されたので、接続できるようになりました。

インスタンスを停止する。

インスタンスがリスナーに登録された状態から、インスタンスを停止させます。

14:00:25 SQL> shutdown immediate
データベースがクローズされました。
データベースがディスマウントされました。
ORACLEインスタンスがシャットダウンされました。
14:14:36 SQL>

リスナーログ抜粋

2015-07-05 14:14:34.271000 +09:00
05-7月 -2015 14:14:34 * service_died * orcl * 12537

インスタンス（プロセス）が停止すると、リスナーから見てサービスは死んだとみなされ「service_died」がログに出力されます。

まとめ

  1. リスナーにインスタンスがサービスとして登録されて初めて、インスタンス（データベース）に対するネット接続が可能となります。
  2. リスナーを後から起動すると、インスタンスが登録するまでにある程度の時間がかかります。（PMONが定期的にリスナーに登録しにいくので最長60秒程度かかる場合があります。）
  3. リスナーを先に起動しておくと、インスタンスは起動直後にリスナーに登録されます。
  4. 2.の場合でも「ALTER SYSTEM REGISTER」コマンドを実行すると、インスタンスを即時にリスナーへ登録することができます。

長くなってしまったので、Oracle12cの結果は次回としたいと思います。

今回はここまで